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/rand915.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand915.sarge-etch-lenny.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand915.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 4/35 12683
/proc/meminfo: memFree=61296/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=0
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894187019 2633728 279 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 279 238 194 0 29 0
[pid=12683] ppid=12682 vsize=3500 CPUtime=0.04
/proc/12683/stat : 12683 (cudf_msu32) R 12682 12682 9023 34817 9081 4202496 675 0 0 0 4 0 0 0 25 0 1 0 894187019 3584000 567 1283457024 134512640 136125367 4294752832 18446744073709551615 134717918 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12683/statm: 875 567 142 394 0 479 0

[startup+0.145512 s]
/proc/loadavg: 0.85 0.94 0.90 4/35 12683
/proc/meminfo: memFree=61296/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=0
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894187019 2633728 279 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 279 238 194 0 29 0
[pid=12683] ppid=12682 vsize=7824 CPUtime=0.14
/proc/12683/stat : 12683 (cudf_msu32) R 12682 12682 9023 34817 9081 4202496 1782 0 0 0 14 0 0 0 25 0 1 0 894187019 8011776 1674 1283457024 134512640 136125367 4294752832 18446744073709551615 134727115 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12683/statm: 1956 1674 142 394 0 1560 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10396

[startup+0.205531 s]
/proc/loadavg: 0.85 0.94 0.90 4/35 12683
/proc/meminfo: memFree=61296/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=0
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894187019 2633728 279 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 279 238 194 0 29 0
[pid=12683] ppid=12682 vsize=9996 CPUtime=0.2
/proc/12683/stat : 12683 (cudf_msu32) R 12682 12682 9023 34817 9081 4202496 2318 0 0 0 20 0 0 0 25 0 1 0 894187019 10235904 2210 1283457024 134512640 136125367 4294752832 18446744073709551615 134717766 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12683/statm: 2499 2210 142 394 0 2103 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12568

[startup+0.305546 s]
/proc/loadavg: 0.85 0.94 0.90 4/35 12683
/proc/meminfo: memFree=61296/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=0
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894187019 2633728 279 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 279 238 194 0 29 0
[pid=12683] ppid=12682 vsize=13492 CPUtime=0.3
/proc/12683/stat : 12683 (cudf_msu32) R 12682 12682 9023 34817 9081 4202496 3178 0 0 0 30 0 0 0 25 0 1 0 894187019 13815808 3070 1283457024 134512640 136125367 4294752832 18446744073709551615 134718529 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12683/statm: 3373 3070 143 394 0 2977 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16064

[startup+0.705616 s]
/proc/loadavg: 0.85 0.94 0.90 4/35 12683
/proc/meminfo: memFree=61296/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=0
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 383 0 0 0 0 0 0 0 25 0 1 0 894187019 2633728 279 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 279 238 194 0 29 0
[pid=12683] ppid=12682 vsize=25060 CPUtime=0.7
/proc/12683/stat : 12683 (cudf_msu32) R 12682 12682 9023 34817 9081 4202496 6078 0 0 0 67 3 0 0 25 0 1 0 894187019 25661440 5970 1283457024 134512640 136125367 4294752832 18446744073709551615 135594622 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/12683/statm: 6265 5970 153 394 0 5869 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27632

[startup+1.50584 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 12684
/proc/meminfo: memFree=25948/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 2572

[startup+3.10631 s]
/proc/loadavg: 0.85 0.94 0.90 2/36 12685
/proc/meminfo: memFree=43184/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=18752 CPUtime=1.64
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 5028 0 0 0 119 45 0 0 25 0 1 0 894187165 19202048 4300 1283457024 134512640 135887319 4287957968 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 4688 4300 138 336 0 4350 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 21324

[startup+6.3072 s]
/proc/loadavg: 0.87 0.94 0.90 2/36 12685
/proc/meminfo: memFree=36984/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=29992 CPUtime=4.84
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 9827 0 0 0 364 120 0 0 25 0 1 0 894187165 30711808 7145 1283457024 134512640 135887319 4287957968 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 7498 7145 144 336 0 7160 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 32564

[startup+12.7092 s]
/proc/loadavg: 0.88 0.94 0.90 2/36 12685
/proc/meminfo: memFree=23972/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=38100 CPUtime=11.2
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 12682 0 0 0 927 193 0 0 25 0 1 0 894187165 39014400 9178 1283457024 134512640 135887319 4287957968 18446744073709551615 134617654 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 9525 9178 144 336 0 9187 0
Current children cumulated CPU time (s) 12.65
Current children cumulated vsize (KiB) 40672

[startup+25.5124 s]
/proc/loadavg: 0.90 0.94 0.90 2/36 12685
/proc/meminfo: memFree=22360/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=39192 CPUtime=24
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 12969 0 0 0 2195 205 0 0 25 0 1 0 894187165 40132608 9457 1283457024 134512640 135887319 4287957968 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 9798 9457 144 336 0 9460 0
Current children cumulated CPU time (s) 25.45
Current children cumulated vsize (KiB) 41764

[startup+51.108 s]
/proc/loadavg: 0.93 0.94 0.90 2/36 12685
/proc/meminfo: memFree=21864/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=39720 CPUtime=49.57
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 13095 0 0 0 4751 206 0 0 25 0 1 0 894187165 40673280 9583 1283457024 134512640 135887319 4287957968 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 9930 9583 144 336 0 9592 0
Current children cumulated CPU time (s) 51.02
Current children cumulated vsize (KiB) 42292

[startup+102.308 s]
/proc/loadavg: 0.97 0.95 0.91 2/36 12685
/proc/meminfo: memFree=20500/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=41040 CPUtime=100.77
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 13438 0 0 0 9869 208 0 0 25 0 1 0 894187165 42024960 9916 1283457024 134512640 135887319 4287957968 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 10260 9916 144 336 0 9922 0
Current children cumulated CPU time (s) 102.22
Current children cumulated vsize (KiB) 43612

[startup+162.311 s]
/proc/loadavg: 0.99 0.95 0.91 2/36 12685
/proc/meminfo: memFree=18392/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=43020 CPUtime=160.75
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 13951 0 0 0 15866 209 0 0 25 0 1 0 894187165 44052480 10421 1283457024 134512640 135887319 4287957968 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 10755 10421 144 336 0 10417 0
Current children cumulated CPU time (s) 162.2
Current children cumulated vsize (KiB) 45592

[startup+222.304 s]
/proc/loadavg: 0.99 0.96 0.91 2/36 12685
/proc/meminfo: memFree=15788/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=45792 CPUtime=220.68
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 14646 0 0 0 21856 212 0 0 25 0 1 0 894187165 46891008 11095 1283457024 134512640 135887319 4287957968 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 11448 11095 144 336 0 11110 0
Current children cumulated CPU time (s) 222.13
Current children cumulated vsize (KiB) 48364

[startup+282.306 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 12685
/proc/meminfo: memFree=13432/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=48056 CPUtime=280.6
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 15263 0 0 0 27846 214 0 0 25 0 1 0 894187165 49209344 11683 1283457024 134512640 135887319 4287957968 18446744073709551615 134603615 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 12014 11683 144 336 0 11676 0
Current children cumulated CPU time (s) 282.05
Current children cumulated vsize (KiB) 50628



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.307 s]
/proc/loadavg: 0.99 0.97 0.91 2/36 12685
/proc/meminfo: memFree=13060/1048576 swapFree=2095372/2097144
[pid=12682] ppid=12681 vsize=2572 CPUtime=1.45
/proc/12682/stat : 12682 (cudf2pbo4trendy) S 12681 12682 9023 34817 9081 4202496 403 9340 0 0 0 0 116 29 18 0 1 0 894187019 2633728 282 1283457024 134512640 135304128 4291901200 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/12682/statm: 643 282 241 194 0 29 0
[pid=12685] ppid=12682 vsize=48452 CPUtime=288.59
/proc/12685/stat : 12685 (bmo-pblex32) R 12682 12682 9023 34817 9081 4202496 15356 0 0 0 28645 214 0 0 25 0 1 0 894187165 49614848 11773 1283457024 134512640 135887319 4287957968 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/12685/statm: 12113 11773 144 336 0 11775 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 51024

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.383
CPU time (s): 290.134
CPU user time (s): 287.686
CPU system time (s): 2.44815
CPU usage (%): 99.9144
Max. virtual memory (cumulated for all children) (KiB): 51024

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 287.686
system time used= 2.44815
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 27055
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= 8028

runsolver used 0 second user time and 0 second system time

The end