runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/9bb87ab4-4c36-11df-bc1e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/debian-dudf//9bb87ab4-4c36-11df-bc1e-00163e7a6f5e.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/9bb87ab4-4c36-11df-bc1e-00163e7a6f5e.cudf.debian-dudf.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.00 1.00 0.92 5/35 13635
/proc/meminfo: memFree=61612/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=0
/proc/13634/stat : 13634 (cudf2pbo4trendy) R 13633 13634 9023 34817 9081 4202496 364 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 278 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/13634/statm: 643 278 238 194 0 29 0
[pid=13635] ppid=13634 vsize=2572 CPUtime=0
/proc/13635/stat : 13635 (cudf2pbo4trendy) R 13634 13634 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 40 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/13635/statm: 643 40 0 194 0 29 0

[startup+0.141122 s]
/proc/loadavg: 1.00 1.00 0.92 5/35 13635
/proc/meminfo: memFree=61612/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=0
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 278 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 278 238 194 0 29 0
[pid=13635] ppid=13634 vsize=7200 CPUtime=0.14
/proc/13635/stat : 13635 (cudf_msu32) R 13634 13634 9023 34817 9081 4202496 1610 0 0 0 14 0 0 0 25 0 1 0 894651249 7372800 1503 1283457024 134512640 136125367 4294527488 18446744073709551615 134717796 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13635/statm: 1800 1503 141 394 0 1404 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 9772

[startup+0.211143 s]
/proc/loadavg: 1.00 1.00 0.92 5/35 13635
/proc/meminfo: memFree=61612/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=0
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 278 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 278 238 194 0 29 0
[pid=13635] ppid=13634 vsize=9708 CPUtime=0.21
/proc/13635/stat : 13635 (cudf_msu32) R 13634 13634 9023 34817 9081 4202496 2250 0 0 0 21 0 0 0 25 0 1 0 894651249 9940992 2143 1283457024 134512640 136125367 4294527488 18446744073709551615 135549054 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13635/statm: 2427 2143 141 394 0 2031 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12280

[startup+0.311172 s]
/proc/loadavg: 1.00 1.00 0.92 5/35 13635
/proc/meminfo: memFree=61612/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=0
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 278 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 278 238 194 0 29 0
[pid=13635] ppid=13634 vsize=12972 CPUtime=0.31
/proc/13635/stat : 13635 (cudf_msu32) R 13634 13634 9023 34817 9081 4202496 3043 0 0 0 30 1 0 0 25 0 1 0 894651249 13283328 2936 1283457024 134512640 136125367 4294527488 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13635/statm: 3243 2936 142 394 0 2847 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15544

[startup+0.711261 s]
/proc/loadavg: 1.00 1.00 0.92 5/35 13635
/proc/meminfo: memFree=61612/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=0
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 278 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 278 238 194 0 29 0
[pid=13635] ppid=13634 vsize=23992 CPUtime=0.7
/proc/13635/stat : 13635 (cudf_msu32) R 13634 13634 9023 34817 9081 4202496 5806 0 0 0 67 3 0 0 25 0 1 0 894651249 24567808 5699 1283457024 134512640 136125367 4294527488 18446744073709551615 135549868 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13635/statm: 5998 5699 142 394 0 5602 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26564

[startup+1.51144 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13636
/proc/meminfo: memFree=33232/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=0
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 25 0 1 0 894651249 2633728 278 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 278 238 194 0 29 0
[pid=13635] ppid=13634 vsize=47112 CPUtime=1.5
/proc/13635/stat : 13635 (cudf_msu32) R 13634 13634 9023 34817 9081 4202496 11698 0 0 0 141 9 0 0 25 0 1 0 894651249 48242688 11492 1283457024 134512640 136125367 4294527488 18446744073709551615 134696515 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/13635/statm: 11778 11492 160 394 0 11382 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 49684

[startup+3.11177 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13636
/proc/meminfo: memFree=5332/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 2.62
Current children cumulated vsize (KiB) 2572

[startup+6.31241 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=30676/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=33480 CPUtime=3.68
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 8794 0 0 0 262 106 0 0 25 0 1 0 894651511 34283520 7866 1283457024 134512640 135887319 4291366656 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 8370 7866 138 336 0 8032 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 36052

[startup+12.7137 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=29188/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=35136 CPUtime=10.07
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 9252 0 0 0 722 285 0 0 25 0 1 0 894651511 35979264 8283 1283457024 134512640 135887319 4291366656 18446744073709551615 134600851 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 8784 8283 138 336 0 8446 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 37708

[startup+25.506 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=26708/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=37464 CPUtime=22.86
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 9927 0 0 0 1733 553 0 0 25 0 1 0 894651511 38363136 8862 1283457024 134512640 135887319 4291366656 18446744073709551615 134600674 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 9366 8862 138 336 0 9028 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 40036

[startup+51.1062 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=6692/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=71676 CPUtime=48.37
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 24300 0 0 0 3815 1022 0 0 25 0 1 0 894651511 73396224 17554 1283457024 134512640 135887319 4291366656 18446744073709551615 134624783 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 17919 17554 144 336 0 17581 0
Current children cumulated CPU time (s) 50.99
Current children cumulated vsize (KiB) 74248

Solver just ended. Dumping a history of the last processes samples

[startup+51.2062 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=6692/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=71812 CPUtime=48.46
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 24311 0 0 0 3824 1022 0 0 25 0 1 0 894651511 73535488 17565 1283457024 134512640 135887319 4291366656 18446744073709551615 134615153 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 17953 17565 144 336 0 17615 0
Current children cumulated CPU time (s) 51.08
Current children cumulated vsize (KiB) 74384

[startup+54.4068 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=5452/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=72928 CPUtime=51.64
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 24607 0 0 0 4099 1065 0 0 25 0 1 0 894651511 74678272 17861 1283457024 134512640 135887319 4291366656 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 18232 17861 144 336 0 17894 0
Current children cumulated CPU time (s) 54.26
Current children cumulated vsize (KiB) 75500

[startup+57.6074 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=5352/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=74044 CPUtime=54.82
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 24900 0 0 0 4391 1091 0 0 25 0 1 0 894651511 75821056 18151 1283457024 134512640 135887319 4291366656 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 18511 18151 144 336 0 18173 0
Current children cumulated CPU time (s) 57.44
Current children cumulated vsize (KiB) 76616

[startup+59.2078 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=6180/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=74592 CPUtime=56.42
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 25059 0 0 0 4536 1106 0 0 25 0 1 0 894651511 76382208 18274 1283457024 134512640 135887319 4291366656 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 18648 18274 144 336 0 18310 0
Current children cumulated CPU time (s) 59.04
Current children cumulated vsize (KiB) 77164

[startup+59.6081 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=5932/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=2.62
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 401 14671 0 0 0 0 208 54 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
[pid=13637] ppid=13634 vsize=74592 CPUtime=56.82
/proc/13637/stat : 13637 (bmo-pblex32) R 13634 13634 9023 34817 9081 4202496 25079 0 0 0 4575 1107 0 0 25 0 1 0 894651511 76382208 18290 1283457024 134512640 135887319 4291366656 18446744073709551615 134605881 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/13637/statm: 18648 18290 144 336 0 18310 0
Current children cumulated CPU time (s) 59.44
Current children cumulated vsize (KiB) 77164

[startup+60.0082 s]
/proc/loadavg: 1.00 1.00 0.92 2/36 13637
/proc/meminfo: memFree=5932/1048576 swapFree=2095372/2097144
[pid=13634] ppid=13633 vsize=2572 CPUtime=59.79
/proc/13634/stat : 13634 (cudf2pbo4trendy) S 13633 13634 9023 34817 9081 4202496 432 39761 0 0 0 0 4817 1162 18 0 1 0 894651249 2633728 281 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/13634/statm: 643 281 241 194 0 29 0
Current children cumulated CPU time (s) 59.79
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 60.0959
CPU time (s): 59.9357
CPU user time (s): 48.295
CPU system time (s): 11.6407
CPU usage (%): 99.7335
Max. virtual memory (cumulated for all children) (KiB): 77296

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 48.295
system time used= 11.6407
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 42524
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 21
involuntary context switches= 5934

runsolver used 0 second user time and 0 second system time

The end