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.cudf.sarge-etch-lenny.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny/rand108.sarge-etch-lenny.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand108.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: 1.28 1.09 1.03 5/45 6186
/proc/meminfo: memFree=656468/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2588 CPUtime=0
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 18 0 1 0 878025271 2650112 281 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/6184/statm: 647 281 237 194 0 33 0
[pid=6185] ppid=6184 vsize=2588 CPUtime=0
/proc/6185/stat : 6185 (aspcud-trendy-1) S 6184 6184 4159 34819 4229 4202560 113 0 0 0 0 0 0 0 25 0 1 0 878025271 2650112 128 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/6185/statm: 647 128 83 194 0 33 0
[pid=6186] ppid=6185 vsize=2588 CPUtime=0
/proc/6186/stat : 6186 (aspcud-trendy-1) R 6185 6184 4159 34819 4229 4202560 124 0 0 0 0 0 0 0 25 0 1 0 878025271 2650112 148 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6186/statm: 647 148 103 194 0 33 0
[pid=6187] ppid=6186 vsize=2588 CPUtime=0
/proc/6187/stat : 6187 (aspcud-trendy-1) R 6186 6184 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 878025271 2650112 45 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6187/statm: 647 45 0 194 0 33 0

[startup+0.192733 s]
/proc/loadavg: 1.28 1.09 1.03 5/45 6186
/proc/meminfo: memFree=656468/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=0
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 2214 0 0 0 0 0 0 25 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.20273 s]
/proc/loadavg: 1.28 1.09 1.03 5/45 6186
/proc/meminfo: memFree=656468/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=0
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 2214 0 0 0 0 0 0 25 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.31274 s]
/proc/loadavg: 1.28 1.09 1.03 5/45 6186
/proc/meminfo: memFree=656468/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=0
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 2214 0 0 0 0 0 0 25 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.71282 s]
/proc/loadavg: 1.28 1.09 1.03 5/45 6186
/proc/meminfo: memFree=656468/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=0
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 2214 0 0 0 0 0 0 25 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51302 s]
/proc/loadavg: 1.33 1.10 1.04 2/47 6198
/proc/meminfo: memFree=616884/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=0.94
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 11335 0 0 0 0 91 3 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=12224 CPUtime=0.06
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 3253 0 0 0 4 2 0 0 18 0 1 0 878025272 12517376 2735 1283457024 134512640 136223643 4288904224 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 3056 2735 174 418 0 2636 0
[pid=6197] ppid=6184 vsize=19668 CPUtime=0.48
/proc/6197/stat : 6197 (gringo) R 6184 6184 4159 34819 4229 4202496 5785 0 0 0 48 0 0 0 18 0 1 0 878025272 20140032 3786 1283457024 134512640 136959103 4290754144 18446744073709551615 135792050 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6197/statm: 4917 3786 256 598 0 4316 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 34488

[startup+3.11334 s]
/proc/loadavg: 1.33 1.10 1.04 3/46 6198
/proc/meminfo: memFree=598424/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=37476 CPUtime=0.96
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 10548 0 0 0 92 4 0 0 19 0 1 0 878025272 38375424 8604 1283457024 134512640 136223643 4288904224 18446744073709551615 134650447 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 9369 8604 223 418 0 8949 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 40072

[startup+6.31399 s]
/proc/loadavg: 1.33 1.10 1.04 2/45 6198
/proc/meminfo: memFree=622372/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=40908 CPUtime=4.16
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 11417 0 0 0 412 4 0 0 25 0 1 0 878025272 41889792 9473 1283457024 134512640 136223643 4288904224 18446744073709551615 134631204 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 10227 9473 225 418 0 9807 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 43504

[startup+12.7055 s]
/proc/loadavg: 1.28 1.10 1.04 2/45 6198
/proc/meminfo: memFree=595588/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=64812 CPUtime=10.54
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 17387 0 0 0 1050 4 0 0 25 0 1 0 878025272 66367488 15443 1283457024 134512640 136223643 4288904224 18446744073709551615 134924372 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 16203 15443 225 418 0 15783 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 67408

[startup+25.5082 s]
/proc/loadavg: 1.24 1.10 1.04 2/45 6198
/proc/meminfo: memFree=566820/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=92948 CPUtime=23.34
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 24662 0 0 0 2327 7 0 0 25 0 1 0 878025272 95178752 22489 1283457024 134512640 136223643 4288904224 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 23237 22489 225 418 0 22817 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 95544

[startup+51.1141 s]
/proc/loadavg: 1.16 1.09 1.04 2/45 6198
/proc/meminfo: memFree=505688/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=154604 CPUtime=48.93
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 40037 0 0 0 4881 12 0 0 25 0 1 0 878025272 158314496 37864 1283457024 134512640 136223643 4288904224 18446744073709551615 134631716 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 38651 37864 225 418 0 38231 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 157200

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

[startup+51.2142 s]
/proc/loadavg: 1.16 1.09 1.04 2/45 6198
/proc/meminfo: memFree=505688/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=154604 CPUtime=49.03
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 40037 0 0 0 4891 12 0 0 25 0 1 0 878025272 158314496 37864 1283457024 134512640 136223643 4288904224 18446744073709551615 134929023 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 38651 37864 225 418 0 38231 0
Current children cumulated CPU time (s) 51.17
Current children cumulated vsize (KiB) 157200

[startup+64.0078 s]
/proc/loadavg: 1.12 1.08 1.03 2/45 6198
/proc/meminfo: memFree=443068/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=217176 CPUtime=61.81
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 55690 0 0 0 6163 18 0 0 25 0 1 0 878025272 222388224 53517 1283457024 134512640 136223643 4288904224 18446744073709551615 134931148 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 54294 53517 225 418 0 53874 0
Current children cumulated CPU time (s) 63.95
Current children cumulated vsize (KiB) 219772

[startup+70.4098 s]
/proc/loadavg: 1.11 1.08 1.03 2/45 6198
/proc/meminfo: memFree=440960/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=219288 CPUtime=68.21
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 56214 0 0 0 6803 18 0 0 25 0 1 0 878025272 224550912 54041 1283457024 134512640 136223643 4288904224 18446744073709551615 134711275 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 54822 54041 225 418 0 54402 0
Current children cumulated CPU time (s) 70.35
Current children cumulated vsize (KiB) 221884

[startup+72.0102 s]
/proc/loadavg: 1.10 1.08 1.03 2/45 6198
/proc/meminfo: memFree=440960/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=219288 CPUtime=69.81
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 56214 0 0 0 6963 18 0 0 25 0 1 0 878025272 224550912 54041 1283457024 134512640 136223643 4288904224 18446744073709551615 134632048 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 54822 54041 225 418 0 54402 0
Current children cumulated CPU time (s) 71.95
Current children cumulated vsize (KiB) 221884

[startup+73.6105 s]
/proc/loadavg: 1.10 1.08 1.03 2/45 6198
/proc/meminfo: memFree=440960/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=219288 CPUtime=71.41
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 56214 0 0 0 7123 18 0 0 25 0 1 0 878025272 224550912 54041 1283457024 134512640 136223643 4288904224 18446744073709551615 134940628 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 54822 54041 225 418 0 54402 0
Current children cumulated CPU time (s) 73.55
Current children cumulated vsize (KiB) 221884

[startup+74.0106 s]
/proc/loadavg: 1.10 1.08 1.03 2/45 6198
/proc/meminfo: memFree=440960/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2596 CPUtime=2.14
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 620 24276 0 0 0 0 207 7 18 0 1 0 878025271 2658304 299 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 649 299 253 194 0 35 0
[pid=6196] ppid=6184 vsize=219288 CPUtime=71.81
/proc/6196/stat : 6196 (clasp) R 6184 6184 4159 34819 4229 4202496 56214 0 0 0 7163 18 0 0 25 0 1 0 878025272 224550912 54041 1283457024 134512640 136223643 4288904224 18446744073709551615 134929649 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6196/statm: 54822 54041 225 418 0 54402 0
Current children cumulated CPU time (s) 73.95
Current children cumulated vsize (KiB) 221884

[startup+74.2033 s]
/proc/loadavg: 1.10 1.08 1.03 2/45 6198
/proc/meminfo: memFree=440960/1048576 swapFree=2077656/2097144
[pid=6184] ppid=6183 vsize=2700 CPUtime=74.12
/proc/6184/stat : 6184 (aspcud-trendy-1) S 6183 6184 4159 34819 4229 4202496 871 82512 0 0 0 0 7384 28 22 0 1 0 878025271 2764800 324 1283457024 134512640 135304128 4293142592 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/6184/statm: 675 324 258 194 0 61 0
Current children cumulated CPU time (s) 74.12
Current children cumulated vsize (KiB) 2700

Child status: 0
Real time (s): 74.2199
CPU time (s): 74.1326
CPU user time (s): 73.8446
CPU system time (s): 0.288018
CPU usage (%): 99.8824
Max. virtual memory (cumulated for all children) (KiB): 221884

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 73.8446
system time used= 0.288018
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 84759
page faults= 1
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1292
involuntary context switches= 1756

runsolver used 0 second user time and 0.012 second system time

The end