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/rand180.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand180.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand180.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.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.85 0.94 0.90 3/39 10220
/proc/meminfo: memFree=67744/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=0
/proc/10219/stat : 10219 (cudf2pbo4trendy) R 10218 10219 9023 34817 9081 4202496 363 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 277 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/10219/statm: 642 277 238 194 0 28 0
[pid=10220] ppid=10219 vsize=2568 CPUtime=0
/proc/10220/stat : 10220 (cudf2pbo4trendy) R 10219 10219 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 39 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/10220/statm: 642 39 0 194 0 28 0

[startup+0.145381 s]
/proc/loadavg: 0.85 0.94 0.90 3/39 10220
/proc/meminfo: memFree=67744/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=0
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 277 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 277 238 194 0 28 0
[pid=10220] ppid=10219 vsize=8056 CPUtime=0.14
/proc/10220/stat : 10220 (cudf_msu32) R 10219 10219 9023 34817 9081 4202496 1823 0 0 0 13 1 0 0 25 0 1 0 892847265 8249344 1716 1283457024 134512640 136125367 4294001024 18446744073709551615 135594526 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10220/statm: 2014 1716 142 394 0 1618 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10624

[startup+0.205397 s]
/proc/loadavg: 0.85 0.94 0.90 3/39 10220
/proc/meminfo: memFree=67744/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=0
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 277 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 277 238 194 0 28 0
[pid=10220] ppid=10219 vsize=10384 CPUtime=0.2
/proc/10220/stat : 10220 (cudf_msu32) R 10219 10219 9023 34817 9081 4202496 2411 0 0 0 19 1 0 0 25 0 1 0 892847265 10633216 2304 1283457024 134512640 136125367 4294001024 18446744073709551615 135549868 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10220/statm: 2596 2304 142 394 0 2200 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12952

[startup+0.305407 s]
/proc/loadavg: 0.85 0.94 0.90 3/39 10220
/proc/meminfo: memFree=67744/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=0
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 277 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 277 238 194 0 28 0
[pid=10220] ppid=10219 vsize=13880 CPUtime=0.3
/proc/10220/stat : 10220 (cudf_msu32) R 10219 10219 9023 34817 9081 4202496 3293 0 0 0 29 1 0 0 25 0 1 0 892847265 14213120 3186 1283457024 134512640 136125367 4294001024 18446744073709551615 134718168 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10220/statm: 3470 3186 143 394 0 3074 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16448

[startup+0.705465 s]
/proc/loadavg: 0.85 0.94 0.90 3/39 10220
/proc/meminfo: memFree=67744/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=0
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 277 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 277 238 194 0 28 0
[pid=10220] ppid=10219 vsize=26220 CPUtime=0.7
/proc/10220/stat : 10220 (cudf_msu32) R 10219 10219 9023 34817 9081 4202496 6366 0 0 0 69 1 0 0 25 0 1 0 892847265 26849280 6259 1283457024 134512640 136125367 4294001024 18446744073709551615 134717776 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10220/statm: 6555 6259 143 394 0 6159 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28788

[startup+1.50541 s]
/proc/loadavg: 0.86 0.95 0.90 2/40 10221
/proc/meminfo: memFree=34988/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=0
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 892847265 2629632 277 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 277 238 194 0 28 0
[pid=10220] ppid=10219 vsize=52380 CPUtime=1.49
/proc/10220/stat : 10220 (cudf_msu32) R 10219 10219 9023 34817 9081 4202496 13274 0 0 0 141 8 0 0 25 0 1 0 892847265 53637120 12826 1283457024 134512640 136125367 4294001024 18446744073709551615 134722480 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/10220/statm: 13095 12826 160 394 0 12699 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 54948

[startup+3.10227 s]
/proc/loadavg: 0.86 0.95 0.90 2/40 10221
/proc/meminfo: memFree=10436/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
Current children cumulated CPU time (s) 2.28
Current children cumulated vsize (KiB) 2568
heavy processes:

[startup+6.30311 s]
/proc/loadavg: 0.87 0.95 0.90 2/40 10222
/proc/meminfo: memFree=32012/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=35220 CPUtime=3.99
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 10590 0 0 0 283 116 0 0 25 0 1 0 892847495 36065280 8367 1283457024 134512640 135887319 4292560928 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 8805 8367 144 336 0 8467 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 37788

[startup+12.7146 s]
/proc/loadavg: 0.88 0.95 0.91 2/40 10222
/proc/meminfo: memFree=31764/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=35356 CPUtime=10.38
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 10642 0 0 0 886 152 0 0 25 0 1 0 892847495 36204544 8419 1283457024 134512640 135887319 4292560928 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 8839 8419 144 336 0 8501 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 37924

[startup+25.5057 s]
/proc/loadavg: 0.90 0.95 0.91 2/40 10222
/proc/meminfo: memFree=23952/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=43236 CPUtime=23.18
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 14409 0 0 0 2148 170 0 0 25 0 1 0 892847495 44273664 10384 1283457024 134512640 135887319 4292560928 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 10809 10384 144 336 0 10471 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 45804

[startup+51.1136 s]
/proc/loadavg: 0.94 0.95 0.91 2/40 10222
/proc/meminfo: memFree=17132/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=49524 CPUtime=48.77
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 17190 0 0 0 4701 176 0 0 25 0 1 0 892847495 50712576 11933 1283457024 134512640 135887319 4292560928 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 12381 11933 144 336 0 12043 0
Current children cumulated CPU time (s) 51.05
Current children cumulated vsize (KiB) 52092

[startup+102.312 s]
/proc/loadavg: 0.97 0.95 0.91 2/40 10222
/proc/meminfo: memFree=5216/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=65940 CPUtime=99.84
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 22114 0 0 0 9562 422 0 0 25 0 1 0 892847495 67522560 16069 1283457024 134512640 135887319 4292560928 18446744073709551615 134526506 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 16485 16069 144 336 0 16147 0
Current children cumulated CPU time (s) 102.12
Current children cumulated vsize (KiB) 68508

[startup+162.309 s]
/proc/loadavg: 0.99 0.96 0.91 2/40 10222
/proc/meminfo: memFree=6452/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=68420 CPUtime=159.78
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 22782 0 0 0 15551 427 0 0 25 0 1 0 892847495 70062080 16695 1283457024 134512640 135887319 4292560928 18446744073709551615 134603613 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 17105 16695 144 336 0 16767 0
Current children cumulated CPU time (s) 162.06
Current children cumulated vsize (KiB) 70988

[startup+222.311 s]
/proc/loadavg: 0.99 0.97 0.91 2/40 10222
/proc/meminfo: memFree=5832/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=68948 CPUtime=219.77
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 22923 0 0 0 21549 428 0 0 25 0 1 0 892847495 70602752 16836 1283457024 134512640 135887319 4292560928 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 17237 16836 144 336 0 16899 0
Current children cumulated CPU time (s) 222.05
Current children cumulated vsize (KiB) 71516

[startup+282.315 s]
/proc/loadavg: 0.99 0.97 0.91 2/41 10226
/proc/meminfo: memFree=5352/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=70700 CPUtime=279.73
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 23390 0 0 0 27540 433 0 0 25 0 1 0 892847495 72396800 17250 1283457024 134512640 135887319 4292560928 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 17675 17250 144 336 0 17337 0
Current children cumulated CPU time (s) 282.01
Current children cumulated vsize (KiB) 73268



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.406 s]
/proc/loadavg: 0.99 0.97 0.91 2/41 10226
/proc/meminfo: memFree=6244/1048576 swapFree=2095372/2097144
[pid=10219] ppid=10218 vsize=2568 CPUtime=2.28
/proc/10219/stat : 10219 (cudf2pbo4trendy) S 10218 10219 9023 34817 9081 4202496 399 14284 0 0 0 0 185 43 18 0 1 0 892847265 2629632 280 1283457024 134512640 135304128 4290375024 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/10219/statm: 642 280 241 194 0 28 0
[pid=10222] ppid=10219 vsize=70964 CPUtime=287.81
/proc/10222/stat : 10222 (bmo-pblex32) R 10219 10219 9023 34817 9081 4202496 23466 0 0 0 28346 435 0 0 25 0 1 0 892847495 72667136 17325 1283457024 134512640 135887319 4292560928 18446744073709551615 134603613 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/10222/statm: 17741 17325 144 336 0 17403 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 73532

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

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

Child status: 0
Real time (s): 290.513
CPU time (s): 290.21
CPU user time (s): 285.386
CPU system time (s): 4.8243
CPU usage (%): 99.8958
Max. virtual memory (cumulated for all children) (KiB): 73532

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 285.386
system time used= 4.8243
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40371
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= 23
involuntary context switches= 12368

runsolver used 0 second user time and 0 second system time

The end