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/201012070034/aspcud-trendy-1.3/rand108.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand108.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand108.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: 1.17 1.15 1.06 2/43 5932
/proc/meminfo: memFree=781044/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=3024 CPUtime=0
/proc/5932/stat : 5932 (runsolver) D 5931 5932 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 877952349 3096576 93 1283457024 134512640 134586868 4287892016 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/5932/statm: 756 93 62 19 0 54 0

[startup+0.193247 s]
/proc/loadavg: 1.17 1.15 1.06 2/43 5932
/proc/meminfo: memFree=781044/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=0
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 624 2214 0 3 0 0 0 0 25 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.211525 s]
/proc/loadavg: 1.17 1.15 1.06 2/43 5932
/proc/meminfo: memFree=781044/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=0
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 624 2214 0 3 0 0 0 0 25 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.311563 s]
/proc/loadavg: 1.17 1.15 1.06 2/43 5932
/proc/meminfo: memFree=781044/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=0
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 624 2214 0 3 0 0 0 0 25 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.711674 s]
/proc/loadavg: 1.17 1.15 1.06 2/43 5932
/proc/meminfo: memFree=781044/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=0
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 624 2214 0 3 0 0 0 0 25 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.51193 s]
/proc/loadavg: 1.32 1.18 1.07 2/47 5946
/proc/meminfo: memFree=741988/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=0
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 624 2214 0 3 0 0 0 0 25 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=3276 CPUtime=0
/proc/5944/stat : 5944 (clasp) S 5932 5932 4159 34819 4229 4202496 663 0 18 0 0 0 0 0 18 0 1 0 877952353 3354624 549 1283457024 134512640 136223643 4289821952 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5944/statm: 819 549 173 418 0 399 0
[pid=5945] ppid=5932 vsize=4692 CPUtime=0.08
/proc/5945/stat : 5945 (gringo) R 5932 5932 4159 34819 4229 4202496 938 0 22 0 8 0 0 0 18 0 1 0 877952353 4804608 731 1283457024 134512640 136959103 4288345104 18446744073709551615 136020707 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5945/statm: 1173 731 247 598 0 572 0
[pid=5946] ppid=5932 vsize=43444 CPUtime=1.24
/proc/5946/stat : 5946 (cudf2lp) R 5932 5932 4159 34819 4229 4202496 14007 0 14 0 120 4 0 0 25 0 1 0 877952353 44486656 10656 1283457024 134512640 135749571 4291314208 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5946/statm: 10861 10656 129 302 0 10557 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 54012

[startup+3.11371 s]
/proc/loadavg: 1.32 1.18 1.07 3/47 5946
/proc/meminfo: memFree=708576/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=1.48
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 16224 0 18 0 0 142 6 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=29300 CPUtime=0.14
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 8223 0 18 0 12 2 0 0 18 0 1 0 877952353 30003200 7045 1283457024 134512640 136223643 4289821952 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 7325 7045 174 418 0 6905 0
[pid=5945] ppid=5932 vsize=46424 CPUtime=1.29
/proc/5945/stat : 5945 (gringo) R 5932 5932 4159 34819 4229 4202496 13761 0 22 0 120 9 0 0 18 0 1 0 877952353 47538176 9457 1283457024 134512640 136959103 4288345104 18446744073709551615 135850573 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5945/statm: 11606 9457 256 598 0 11005 0
Current children cumulated CPU time (s) 2.91
Current children cumulated vsize (KiB) 78324

[startup+6.31451 s]
/proc/loadavg: 1.29 1.18 1.07 2/45 5946
/proc/meminfo: memFree=724112/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=56340 CPUtime=2.67
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 16299 0 19 0 264 3 0 0 22 0 1 0 877952353 57692160 13003 1283457024 134512640 136223643 4289821952 18446744073709551615 134870640 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 14085 13003 222 418 0 13665 0
Current children cumulated CPU time (s) 6.1
Current children cumulated vsize (KiB) 58940

[startup+12.7063 s]
/proc/loadavg: 1.27 1.17 1.07 2/45 5946
/proc/meminfo: memFree=724120/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=56868 CPUtime=9.05
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 16437 0 19 0 902 3 0 0 25 0 1 0 877952353 58232832 13141 1283457024 134512640 136223643 4289821952 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 14217 13141 225 418 0 13797 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 59468

[startup+25.5092 s]
/proc/loadavg: 1.21 1.16 1.07 2/45 5946
/proc/meminfo: memFree=700808/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=80100 CPUtime=21.83
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 22249 0 19 0 2177 6 0 0 25 0 1 0 877952353 82022400 18953 1283457024 134512640 136223643 4289821952 18446744073709551615 134917906 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 20025 18953 225 418 0 19605 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 82700

[startup+51.1064 s]
/proc/loadavg: 1.14 1.15 1.07 2/45 5946
/proc/meminfo: memFree=658524/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=122484 CPUtime=47.42
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 32804 0 19 0 4729 13 0 0 25 0 1 0 877952353 125423616 29508 1283457024 134512640 136223643 4289821952 18446744073709551615 134630805 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 30621 29508 225 418 0 30201 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 125084

[startup+102.307 s]
/proc/loadavg: 1.06 1.12 1.06 2/45 5946
/proc/meminfo: memFree=624300/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=155840 CPUtime=98.56
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 41690 0 19 0 9843 13 0 0 25 0 1 0 877952353 159580160 37877 1283457024 134512640 136223643 4289821952 18446744073709551615 134709559 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 38960 37877 225 418 0 38540 0
Current children cumulated CPU time (s) 101.99
Current children cumulated vsize (KiB) 158440

[startup+162.313 s]
/proc/loadavg: 1.02 1.10 1.06 2/45 5946
/proc/meminfo: memFree=484924/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=299552 CPUtime=158.51
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 77533 0 19 0 15817 34 0 0 25 0 1 0 877952353 306741248 73720 1283457024 134512640 136223643 4289821952 18446744073709551615 134931334 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 74888 73720 225 418 0 74468 0
Current children cumulated CPU time (s) 161.94
Current children cumulated vsize (KiB) 302152

[startup+222.312 s]
/proc/loadavg: 1.00 1.08 1.05 2/45 5946
/proc/meminfo: memFree=476492/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=303448 CPUtime=218.46
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 79280 0 19 0 21812 34 0 0 25 0 1 0 877952353 310730752 74730 1283457024 134512640 136223643 4289821952 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 75862 74730 225 418 0 75442 0
Current children cumulated CPU time (s) 221.89
Current children cumulated vsize (KiB) 306048

[startup+282.308 s]
/proc/loadavg: 1.00 1.06 1.05 2/45 5946
/proc/meminfo: memFree=402216/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=381884 CPUtime=278.42
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 98935 0 19 0 27800 42 0 0 25 0 1 0 877952353 391049216 94280 1283457024 134512640 136223643 4289821952 18446744073709551615 134929050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 95471 94280 225 418 0 95051 0
Current children cumulated CPU time (s) 281.85
Current children cumulated vsize (KiB) 384484



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.511 s]
/proc/loadavg: 1.00 1.06 1.04 2/45 5946
/proc/meminfo: memFree=382872/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=397812 CPUtime=286.58
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 102896 0 19 0 28614 44 0 0 25 0 1 0 877952353 407359488 98241 1283457024 134512640 136223643 4289821952 18446744073709551615 134629634 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 99453 98241 225 418 0 99033 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 400412

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.511 s]
/proc/loadavg: 1.00 1.06 1.04 2/45 5946
/proc/meminfo: memFree=382872/1048576 swapFree=2077656/2097144
[pid=5932] ppid=5931 vsize=2600 CPUtime=3.43
/proc/5932/stat : 5932 (aspcud-trendy-1) S 5931 5932 4159 34819 4229 4202496 625 34943 0 40 0 0 327 16 18 0 1 0 877952349 2662400 300 1283457024 134512640 135304128 4292310864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5932/statm: 650 300 253 194 0 36 0
[pid=5944] ppid=5932 vsize=397812 CPUtime=286.58
/proc/5944/stat : 5944 (clasp) R 5932 5932 4159 34819 4229 4202496 102896 0 19 0 28614 44 0 0 25 0 1 0 877952353 407359488 98241 1283457024 134512640 136223643 4289821952 18446744073709551615 134629634 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5944/statm: 99453 98241 225 418 0 99033 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 400412

Child status: 0
Real time (s): 290.563
CPU time (s): 290.062
CPU user time (s): 289.422
CPU system time (s): 0.64004
CPU usage (%): 99.8275
Max. virtual memory (cumulated for all children) (KiB): 400412

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.422
system time used= 0.64004
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 141083
page faults= 60
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2782
involuntary context switches= 5574

runsolver used 0 second user time and 0 second system time

The end