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/cudf2pbo4paranoid-1.0/rand165.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand165.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/rand165.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.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: 0.84 0.93 0.90 3/39 9763
/proc/meminfo: memFree=117692/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=0
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892525236 2633728 278 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 278 238 194 0 29 0
[pid=9763] ppid=9762 vsize=1920 CPUtime=0
/proc/9763/stat : 9763 (cudf_msu32) D 9762 9762 9023 34817 9081 4202496 265 0 0 0 0 0 0 0 18 0 1 0 892525237 1966080 157 1283457024 134512640 136125367 4293200048 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/9763/statm: 480 157 133 394 0 84 0

[startup+0.195016 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9763
/proc/meminfo: memFree=117692/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=0
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892525236 2633728 278 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 278 238 194 0 29 0
[pid=9763] ppid=9762 vsize=9504 CPUtime=0.17
/proc/9763/stat : 9763 (cudf_msu32) R 9762 9762 9023 34817 9081 4202496 2190 0 0 0 16 1 0 0 25 0 1 0 892525237 9732096 2082 1283457024 134512640 136125367 4293200048 18446744073709551615 134717890 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9763/statm: 2376 2082 143 394 0 1980 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12076

[startup+0.204344 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9763
/proc/meminfo: memFree=117692/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=0
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892525236 2633728 278 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 278 238 194 0 29 0
[pid=9763] ppid=9762 vsize=9900 CPUtime=0.17
/proc/9763/stat : 9763 (cudf_msu32) D 9762 9762 9023 34817 9081 4202496 2270 0 0 0 16 1 0 0 25 0 1 0 892525237 10137600 2162 1283457024 134512640 136125367 4293200048 18446744073709551615 135594526 0 0 0 25121 18446744071564332000 0 0 17 0 0 0 0
/proc/9763/statm: 2475 2162 143 394 0 2079 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12472

[startup+0.304359 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9763
/proc/meminfo: memFree=117692/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=0
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892525236 2633728 278 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 278 238 194 0 29 0
[pid=9763] ppid=9762 vsize=13264 CPUtime=0.27
/proc/9763/stat : 9763 (cudf_msu32) R 9762 9762 9023 34817 9081 4202496 3132 0 0 0 25 2 0 0 25 0 1 0 892525237 13582336 3024 1283457024 134512640 136125367 4293200048 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9763/statm: 3316 3024 144 394 0 2920 0
Current children cumulated CPU time (s) 0.27
Current children cumulated vsize (KiB) 15836

[startup+0.704384 s]
/proc/loadavg: 0.84 0.93 0.90 3/39 9763
/proc/meminfo: memFree=117692/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=0
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892525236 2633728 278 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 278 238 194 0 29 0
[pid=9763] ppid=9762 vsize=25340 CPUtime=0.62
/proc/9763/stat : 9763 (cudf_msu32) R 9762 9762 9023 34817 9081 4202496 6142 0 0 0 59 3 0 0 25 0 1 0 892525237 25948160 6034 1283457024 134512640 136125367 4293200048 18446744073709551615 134727103 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9763/statm: 6335 6034 144 394 0 5939 0
Current children cumulated CPU time (s) 0.62
Current children cumulated vsize (KiB) 27912

[startup+1.50794 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 9764
/proc/meminfo: memFree=66208/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=0
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892525236 2633728 278 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 278 238 194 0 29 0
[pid=9763] ppid=9762 vsize=49276 CPUtime=1.33
/proc/9763/stat : 9763 (cudf_msu32) R 9762 9762 9023 34817 9081 4202496 12195 0 0 0 125 8 0 0 25 0 1 0 892525237 50458624 12038 1283457024 134512640 136125367 4293200048 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/9763/statm: 12319 12038 165 394 0 11923 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 51848

[startup+3.10831 s]
/proc/loadavg: 0.85 0.94 0.90 2/40 9765
/proc/meminfo: memFree=81000/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=16688 CPUtime=1.2
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 4514 0 0 0 92 28 0 0 25 0 1 0 892525428 17088512 3894 1283457024 134512640 135887319 4293638432 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 4172 3894 138 336 0 3834 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 19260

[startup+6.30472 s]
/proc/loadavg: 0.87 0.94 0.90 2/40 9765
/proc/meminfo: memFree=75420/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=22796 CPUtime=4.31
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 6783 0 0 0 355 76 0 0 25 0 1 0 892525428 23343104 5417 1283457024 134512640 135887319 4293638432 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 5699 5417 144 336 0 5361 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 25368

[startup+12.7092 s]
/proc/loadavg: 0.88 0.94 0.90 2/40 9765
/proc/meminfo: memFree=70832/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=26796 CPUtime=10.67
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 7794 0 0 0 946 121 0 0 25 0 1 0 892525428 27439104 6407 1283457024 134512640 135887319 4293638432 18446744073709551615 134603310 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 6699 6407 144 336 0 6361 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 29368

[startup+25.5125 s]
/proc/loadavg: 0.89 0.94 0.90 2/40 9765
/proc/meminfo: memFree=66616/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=30900 CPUtime=23.45
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 8897 0 0 0 2217 128 0 0 25 0 1 0 892525428 31641600 7441 1283457024 134512640 135887319 4293638432 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 7725 7441 144 336 0 7387 0
Current children cumulated CPU time (s) 25.17
Current children cumulated vsize (KiB) 33472

[startup+51.1077 s]
/proc/loadavg: 0.93 0.94 0.90 2/40 9765
/proc/meminfo: memFree=58308/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=39428 CPUtime=49.02
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 11190 0 0 0 4767 135 0 0 25 0 1 0 892525428 40374272 9551 1283457024 134512640 135887319 4293638432 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 9857 9551 144 336 0 9519 0
Current children cumulated CPU time (s) 50.74
Current children cumulated vsize (KiB) 42000

[startup+102.313 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 9765
/proc/meminfo: memFree=45288/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=52296 CPUtime=100.13
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 14819 0 0 0 9864 149 0 0 25 0 1 0 892525428 53551104 12714 1283457024 134512640 135887319 4293638432 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 13074 12714 144 336 0 12736 0
Current children cumulated CPU time (s) 101.85
Current children cumulated vsize (KiB) 54868

[startup+162.307 s]
/proc/loadavg: 0.99 0.95 0.91 2/40 9765
/proc/meminfo: memFree=39460/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=58080 CPUtime=160.05
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 16427 0 0 0 15836 169 0 0 25 0 1 0 892525428 59473920 14188 1283457024 134512640 135887319 4293638432 18446744073709551615 134611425 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 14520 14188 144 336 0 14182 0
Current children cumulated CPU time (s) 161.77
Current children cumulated vsize (KiB) 60652

[startup+222.31 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 9765
/proc/meminfo: memFree=39212/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=58080 CPUtime=219.99
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 16437 0 0 0 21806 193 0 0 25 0 1 0 892525428 59473920 14198 1283457024 134512640 135887319 4293638432 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 14520 14198 144 336 0 14182 0
Current children cumulated CPU time (s) 221.71
Current children cumulated vsize (KiB) 60652

[startup+282.311 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 9765
/proc/meminfo: memFree=32516/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=64972 CPUtime=279.94
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 18208 0 0 0 27778 216 0 0 25 0 1 0 892525428 66531328 15858 1283457024 134512640 135887319 4293638432 18446744073709551615 134624330 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 16243 15858 144 336 0 15905 0
Current children cumulated CPU time (s) 281.66
Current children cumulated vsize (KiB) 67544



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.703 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 9765
/proc/meminfo: memFree=32516/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=64972 CPUtime=288.33
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 18208 0 0 0 28613 220 0 0 25 0 1 0 892525428 66531328 15858 1283457024 134512640 135887319 4293638432 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 16243 15858 144 336 0 15905 0
Current children cumulated CPU time (s) 290.05
Current children cumulated vsize (KiB) 67544

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+290.703 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 9765
/proc/meminfo: memFree=32516/1048576 swapFree=2095372/2097144
[pid=9762] ppid=9761 vsize=2572 CPUtime=1.72
/proc/9762/stat : 9762 (cudf2pbo4parano) S 9761 9762 9023 34817 9081 4202496 401 12197 0 0 0 0 146 26 20 0 1 0 892525236 2633728 281 1283457024 134512640 135304128 4293580912 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/9762/statm: 643 281 241 194 0 29 0
[pid=9765] ppid=9762 vsize=64972 CPUtime=288.33
/proc/9765/stat : 9765 (bmo-pblex32) R 9762 9762 9023 34817 9081 4202496 18208 0 0 0 28613 220 0 0 25 0 1 0 892525428 66531328 15858 1283457024 134512640 135887319 4293638432 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/9765/statm: 16243 15858 144 336 0 15905 0
Current children cumulated CPU time (s) 290.05
Current children cumulated vsize (KiB) 67544

Child status: 0
Real time (s): 290.777
CPU time (s): 290.142
CPU user time (s): 287.65
CPU system time (s): 2.49216
CPU usage (%): 99.7817
Max. virtual memory (cumulated for all children) (KiB): 67544

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 287.65
system time used= 2.49215
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 32742
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= 55
involuntary context switches= 7304

runsolver used 0.008 second user time and 0 second system time

The end