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/201012061533/aspcud-paranoid-1.3/rand165.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./aspcud-paranoid-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand165.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012061533/aspcud-paranoid-1.3/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: 1.36 1.21 1.17 5/46 6248
/proc/meminfo: memFree=622292/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2588 CPUtime=0
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 375 0 0 0 0 0 0 0 25 0 1 0 874647163 2650112 282 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/6247/statm: 647 282 237 194 0 33 0
[pid=6248] ppid=6247 vsize=2588 CPUtime=0
/proc/6248/stat : 6248 (aspcud-paranoid) R 6247 6247 2059 34821 2220 4202560 105 0 0 0 0 0 0 0 25 0 1 0 874647163 2650112 128 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6248/statm: 647 128 82 194 0 33 0
[pid=6249] ppid=6248 vsize=2588 CPUtime=0
/proc/6249/stat : 6249 (aspcud-paranoid) R 6248 6247 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 874647164 2650112 46 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6249/statm: 647 46 0 194 0 33 0

[startup+0.193417 s]
/proc/loadavg: 1.36 1.21 1.17 5/46 6248
/proc/meminfo: memFree=622292/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=0
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 657 2930 0 0 0 0 0 0 25 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.203393 s]
/proc/loadavg: 1.36 1.21 1.17 5/46 6248
/proc/meminfo: memFree=622292/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=0
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 657 2930 0 0 0 0 0 0 25 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.313402 s]
/proc/loadavg: 1.36 1.21 1.17 5/46 6248
/proc/meminfo: memFree=622292/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=0
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 657 2930 0 0 0 0 0 0 25 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.713514 s]
/proc/loadavg: 1.36 1.21 1.17 5/46 6248
/proc/meminfo: memFree=622292/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=0
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 657 2930 0 0 0 0 0 0 25 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+1.51375 s]
/proc/loadavg: 1.36 1.21 1.17 2/49 6264
/proc/meminfo: memFree=579964/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=0
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 657 2930 0 0 0 0 0 0 25 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=5092 CPUtime=0.01
/proc/6262/stat : 6262 (clasp) S 6247 6247 2059 34821 2220 4202496 1112 0 0 0 0 1 0 0 18 0 1 0 874647165 5214208 980 1283457024 134512640 136223643 4288314256 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6262/statm: 1273 980 174 418 0 853 0
[pid=6263] ppid=6247 vsize=7068 CPUtime=0.16
/proc/6263/stat : 6263 (gringo) R 6247 6247 2059 34821 2220 4202496 1718 0 0 0 14 2 0 0 18 0 1 0 874647165 7237632 1215 1283457024 134512640 136959103 4292732992 18446744073709551615 136286705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6263/statm: 1767 1215 247 598 0 1166 0
[pid=6264] ppid=6247 vsize=45404 CPUtime=1.31
/proc/6264/stat : 6264 (cudf2lp) R 6247 6247 2059 34821 2220 4202496 14557 0 0 0 126 5 0 0 25 0 1 0 874647165 46493696 11145 1283457024 134512640 135749571 4288756880 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/6264/statm: 11351 11145 129 302 0 11047 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 60164

[startup+3.10481 s]
/proc/loadavg: 1.36 1.21 1.17 3/48 6264
/proc/meminfo: memFree=593248/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=36744 CPUtime=0.21
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 9837 0 0 0 16 5 0 0 18 0 1 0 874647165 37625856 8203 1283457024 134512640 136223643 4288314256 18446744073709551615 134788496 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 9186 8203 192 418 0 8766 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 39344

[startup+6.30574 s]
/proc/loadavg: 1.33 1.20 1.17 2/47 6264
/proc/meminfo: memFree=588180/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=37072 CPUtime=3.41
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 10738 0 0 0 336 5 0 0 25 0 1 0 874647165 37961728 8536 1283457024 134512640 136223643 4288314256 18446744073709551615 134924702 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 9268 8536 225 418 0 8848 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 39672

[startup+12.7074 s]
/proc/loadavg: 1.30 1.20 1.17 2/47 6264
/proc/meminfo: memFree=584088/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=46184 CPUtime=9.82
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 13022 0 0 0 976 6 0 0 25 0 1 0 874647165 47292416 10820 1283457024 134512640 136223643 4288314256 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 11546 10820 225 418 0 11126 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 48784

[startup+25.5101 s]
/proc/loadavg: 1.24 1.19 1.16 2/47 6264
/proc/meminfo: memFree=564000/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=61892 CPUtime=22.6
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 16926 0 0 0 2252 8 0 0 25 0 1 0 874647165 63377408 14724 1283457024 134512640 136223643 4288314256 18446744073709551615 134712067 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 15473 14724 225 418 0 15053 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 64492

[startup+51.1119 s]
/proc/loadavg: 1.15 1.17 1.16 2/47 6264
/proc/meminfo: memFree=524568/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=101360 CPUtime=48.18
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 27260 0 0 0 4810 8 0 0 25 0 1 0 874647165 103792640 24548 1283457024 134512640 136223643 4288314256 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 25340 24548 225 418 0 24920 0
Current children cumulated CPU time (s) 51.05
Current children cumulated vsize (KiB) 103960

[startup+102.312 s]
/proc/loadavg: 1.07 1.14 1.15 2/47 6264
/proc/meminfo: memFree=470940/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=154632 CPUtime=99.31
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 40578 0 0 0 9919 12 0 0 25 0 1 0 874647165 158343168 37866 1283457024 134512640 136223643 4288314256 18446744073709551615 134920292 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 38658 37866 225 418 0 38238 0
Current children cumulated CPU time (s) 102.18
Current children cumulated vsize (KiB) 157232

[startup+162.308 s]
/proc/loadavg: 1.02 1.11 1.14 2/47 6264
/proc/meminfo: memFree=421960/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=203652 CPUtime=159.25
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 52895 0 0 0 15906 19 0 0 25 0 1 0 874647165 208539648 50078 1283457024 134512640 136223643 4288314256 18446744073709551615 134928992 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 50913 50078 225 418 0 50493 0
Current children cumulated CPU time (s) 162.12
Current children cumulated vsize (KiB) 206252

[startup+222.313 s]
/proc/loadavg: 1.01 1.09 1.13 2/47 6264
/proc/meminfo: memFree=423572/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=202000 CPUtime=219.19
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 53338 0 0 0 21900 19 0 0 25 0 1 0 874647165 206848000 49657 1283457024 134512640 136223643 4288314256 18446744073709551615 134940530 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 50500 49657 225 418 0 50080 0
Current children cumulated CPU time (s) 222.06
Current children cumulated vsize (KiB) 204600

[startup+282.309 s]
/proc/loadavg: 1.00 1.07 1.12 2/47 6264
/proc/meminfo: memFree=424564/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=200812 CPUtime=279.16
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 53758 0 0 0 27896 20 0 0 25 0 1 0 874647165 205631488 49381 1283457024 134512640 136223643 4288314256 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 50203 49381 225 418 0 49783 0
Current children cumulated CPU time (s) 282.03
Current children cumulated vsize (KiB) 203412



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.311 s]
/proc/loadavg: 1.00 1.07 1.11 2/47 6264
/proc/meminfo: memFree=424192/1048576 swapFree=2078764/2097144
[pid=6247] ppid=6246 vsize=2600 CPUtime=2.87
/proc/6247/stat : 6247 (aspcud-paranoid) S 6246 6247 2059 34821 2220 4202496 658 30530 0 0 0 0 271 16 18 0 1 0 874647163 2662400 301 1283457024 134512640 135304128 4293574768 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6247/statm: 650 301 253 194 0 36 0
[pid=6262] ppid=6247 vsize=201208 CPUtime=287.13
/proc/6262/stat : 6262 (clasp) R 6247 6247 2059 34821 2220 4202496 53860 0 0 0 28693 20 0 0 25 0 1 0 874647165 206036992 49483 1283457024 134512640 136223643 4288314256 18446744073709551615 134650832 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6262/statm: 50302 49483 225 418 0 49882 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 203808

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.34
CPU time (s): 290.03
CPU user time (s): 289.646
CPU system time (s): 0.384024
CPU usage (%): 99.8934
Max. virtual memory (cumulated for all children) (KiB): 206252

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.646
system time used= 0.384024
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 87642
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= 1461
involuntary context switches= 4642

runsolver used 0 second user time and 0.012 second system time

The end