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/rand753.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand753.sarge-etch-lenny.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand753.sarge-etch-lenny.cudf.sarge-etch-lenny.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 5/35 11887
/proc/meminfo: memFree=56148/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=0
/proc/11886/stat : 11886 (cudf2pbo4trendy) R 11885 11886 9023 34817 9081 4202496 366 0 0 0 0 0 0 0 25 0 1 0 893787585 2637824 279 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/11886/statm: 644 279 238 194 0 30 0
[pid=11887] ppid=11886 vsize=2576 CPUtime=0
/proc/11887/stat : 11887 (cudf2pbo4trendy) R 11886 11886 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 893787585 2637824 41 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/11887/statm: 644 41 0 194 0 30 0

[startup+0.201147 s]
/proc/loadavg: 0.85 0.94 0.90 5/35 11887
/proc/meminfo: memFree=56148/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=0
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 893787585 2637824 279 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 279 238 194 0 30 0
[pid=11887] ppid=11886 vsize=10000 CPUtime=0.2
/proc/11887/stat : 11887 (cudf_msu32) R 11886 11886 9023 34817 9081 4202496 2293 0 0 0 20 0 0 0 25 0 1 0 893787585 10240000 2185 1283457024 134512640 136125367 4289664368 18446744073709551615 134585315 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11887/statm: 2500 2185 142 394 0 2104 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12576

[startup+0.311176 s]
/proc/loadavg: 0.85 0.94 0.90 5/35 11887
/proc/meminfo: memFree=56148/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=0
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 893787585 2637824 279 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 279 238 194 0 30 0
[pid=11887] ppid=11886 vsize=13628 CPUtime=0.31
/proc/11887/stat : 11887 (cudf_msu32) R 11886 11886 9023 34817 9081 4202496 3229 0 0 0 31 0 0 0 25 0 1 0 893787585 13955072 3121 1283457024 134512640 136125367 4289664368 18446744073709551615 135549056 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11887/statm: 3407 3121 143 394 0 3011 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16204

[startup+0.411205 s]
/proc/loadavg: 0.85 0.94 0.90 5/35 11887
/proc/meminfo: memFree=56148/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=0
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 893787585 2637824 279 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 279 238 194 0 30 0
[pid=11887] ppid=11886 vsize=16796 CPUtime=0.4
/proc/11887/stat : 11887 (cudf_msu32) R 11886 11886 9023 34817 9081 4202496 4002 0 0 0 40 0 0 0 25 0 1 0 893787585 17199104 3894 1283457024 134512640 136125367 4289664368 18446744073709551615 135543652 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11887/statm: 4199 3894 143 394 0 3803 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 19372

[startup+0.711296 s]
/proc/loadavg: 0.85 0.94 0.90 5/35 11887
/proc/meminfo: memFree=56148/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=0
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 384 0 0 0 0 0 0 0 25 0 1 0 893787585 2637824 279 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 279 238 194 0 30 0
[pid=11887] ppid=11886 vsize=25064 CPUtime=0.71
/proc/11887/stat : 11887 (cudf_msu32) R 11886 11886 9023 34817 9081 4202496 6102 0 0 0 69 2 0 0 25 0 1 0 893787585 25665536 5994 1283457024 134512640 136125367 4289664368 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/11887/statm: 6266 5994 153 394 0 5870 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 27640

[startup+1.51154 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 11888
/proc/meminfo: memFree=20044/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) R 11885 11886 9023 34817 9081 4202496 388 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 2576

[startup+3.1021 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 11889
/proc/meminfo: memFree=38148/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=18540 CPUtime=1.66
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 4996 0 0 0 108 58 0 0 25 0 1 0 893787730 18984960 4266 1283457024 134512640 135887319 4287503200 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 4635 4266 138 336 0 4297 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 21116

[startup+6.30288 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 11889
/proc/meminfo: memFree=32072/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=29760 CPUtime=4.85
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 9741 0 0 0 343 142 0 0 25 0 1 0 893787730 30474240 7092 1283457024 134512640 135887319 4287503200 18446744073709551615 134624419 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 7440 7092 144 336 0 7102 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 32336

[startup+12.7148 s]
/proc/loadavg: 0.88 0.94 0.90 2/36 11889
/proc/meminfo: memFree=20548/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=35872 CPUtime=11.24
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 12284 0 0 0 940 184 0 0 25 0 1 0 893787730 36732928 8607 1283457024 134512640 135887319 4287503200 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 8968 8607 144 336 0 8630 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 38448

[startup+25.5074 s]
/proc/loadavg: 0.90 0.94 0.90 2/36 11889
/proc/meminfo: memFree=20548/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=35872 CPUtime=24.03
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 12317 0 0 0 2219 184 0 0 25 0 1 0 893787730 36732928 8634 1283457024 134512640 135887319 4287503200 18446744073709551615 134603619 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 8968 8634 144 336 0 8630 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 38448

[startup+51.1138 s]
/proc/loadavg: 0.93 0.94 0.90 2/36 11889
/proc/meminfo: memFree=20300/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=36140 CPUtime=49.61
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 12380 0 0 0 4774 187 0 0 25 0 1 0 893787730 37007360 8695 1283457024 134512640 135887319 4287503200 18446744073709551615 134603630 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 9035 8695 144 336 0 8697 0
Current children cumulated CPU time (s) 51.04
Current children cumulated vsize (KiB) 38716

[startup+102.314 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 11889
/proc/meminfo: memFree=19184/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=37216 CPUtime=100.8
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 12667 0 0 0 9888 192 0 0 25 0 1 0 893787730 38109184 8961 1283457024 134512640 135887319 4287503200 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 9304 8961 144 336 0 8966 0
Current children cumulated CPU time (s) 102.23
Current children cumulated vsize (KiB) 39792

[startup+162.305 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 11889
/proc/meminfo: memFree=17944/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=38536 CPUtime=160.75
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 12981 0 0 0 15880 195 0 0 25 0 1 0 893787730 39460864 9272 1283457024 134512640 135887319 4287503200 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 9634 9272 144 336 0 9296 0
Current children cumulated CPU time (s) 162.18
Current children cumulated vsize (KiB) 41112

[startup+222.308 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 11889
/proc/meminfo: memFree=16580/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=39724 CPUtime=220.73
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 13299 0 0 0 21876 197 0 0 25 0 1 0 893787730 40677376 9583 1283457024 134512640 135887319 4287503200 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 9931 9583 144 336 0 9593 0
Current children cumulated CPU time (s) 222.16
Current children cumulated vsize (KiB) 42300

[startup+282.313 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11889
/proc/meminfo: memFree=14968/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=41440 CPUtime=280.68
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 13732 0 0 0 27871 197 0 0 25 0 1 0 893787730 42434560 10007 1283457024 134512640 135887319 4287503200 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 10360 10007 144 336 0 10022 0
Current children cumulated CPU time (s) 282.11
Current children cumulated vsize (KiB) 44016



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.205 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 11889
/proc/meminfo: memFree=14720/1048576 swapFree=2095372/2097144
[pid=11886] ppid=11885 vsize=2576 CPUtime=1.43
/proc/11886/stat : 11886 (cudf2pbo4trendy) S 11885 11886 9023 34817 9081 4202496 404 9339 0 0 0 0 120 23 18 0 1 0 893787585 2637824 282 1283457024 134512640 135304128 4288242576 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/11886/statm: 644 282 241 194 0 30 0
[pid=11889] ppid=11886 vsize=41572 CPUtime=288.57
/proc/11889/stat : 11889 (bmo-pblex32) R 11886 11886 9023 34817 9081 4202496 13774 0 0 0 28660 197 0 0 25 0 1 0 893787730 42569728 10049 1283457024 134512640 135887319 4287503200 18446744073709551615 134603579 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/11889/statm: 10393 10049 144 336 0 10055 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 44148

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.28
CPU time (s): 290.094
CPU user time (s): 287.858
CPU system time (s): 2.23614
CPU usage (%): 99.9361
Max. virtual memory (cumulated for all children) (KiB): 44148

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 287.858
system time used= 2.23614
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25444
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= 13
involuntary context switches= 5889

runsolver used 0 second user time and 0 second system time

The end