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/rand81406f.cudf.impossible.log.runsolver ./aspcud-paranoid-1.3 /home/misc2010/data/2010/impossible//rand81406f.cudf /home/misc2010/tmp/201012061533/aspcud-paranoid-1.3/rand81406f.cudf.impossible.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

[startup+0 s]
/proc/loadavg: 1.58 1.34 1.21 2/45 21220
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=3024 CPUtime=0
/proc/21220/stat : 21220 (runsolver) R 21219 2220 2059 34821 2220 4202560 25 0 0 0 0 0 0 0 25 0 1 0 875998608 3096576 48 1283457024 134512640 134586868 4294211744 18446744073709551615 4160479696 0 0 0 24578 0 0 0 17 0 0 0 0
/proc/21220/statm: 756 48 16 19 0 54 0
Current StackSize limit: 8192 KiB


[startup+0.116279 s]
/proc/loadavg: 1.58 1.34 1.21 2/45 21220
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=0
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 663 2929 0 3 0 0 0 0 25 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204261 s]
/proc/loadavg: 1.58 1.34 1.21 2/45 21220
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=0
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 663 2929 0 3 0 0 0 0 25 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.309193 s]
/proc/loadavg: 1.58 1.34 1.21 2/45 21220
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=0
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 663 2929 0 3 0 0 0 0 25 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.709249 s]
/proc/loadavg: 1.58 1.34 1.21 2/45 21220
/proc/meminfo: memFree=901852/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=0
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 663 2929 0 3 0 0 0 0 25 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50934 s]
/proc/loadavg: 1.58 1.34 1.21 2/49 21237
/proc/meminfo: memFree=863904/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=0
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 663 2929 0 3 0 0 0 0 25 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
[pid=21235] ppid=21220 vsize=1872 CPUtime=0
/proc/21235/stat : 21235 (clasp) S 21220 21220 2059 34821 2220 4202496 270 0 15 0 0 0 0 0 24 0 1 0 875998614 1916928 153 1283457024 134512640 136223643 4290524576 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/21235/statm: 468 153 138 418 0 48 0
[pid=21236] ppid=21220 vsize=2604 CPUtime=0
/proc/21236/stat : 21236 (gringo) S 21220 21220 2059 34821 2220 4202496 383 0 23 0 0 0 0 0 23 0 1 0 875998614 2666496 276 1283457024 134512640 136959103 4294410704 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/21236/statm: 651 276 247 598 0 50 0
[pid=21237] ppid=21220 vsize=49824 CPUtime=1.26
/proc/21237/stat : 21237 (cudf2lp) R 21220 21220 2059 34821 2220 4202496 13790 0 14 0 118 8 0 0 25 0 1 0 875998614 51019776 11650 1283457024 134512640 135749571 4290989744 18446744073709551615 134543479 0 0 6 0 0 0 0 17 0 0 0 0
/proc/21237/statm: 12456 11650 127 302 0 12152 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 56896

[startup+3.10973 s]
/proc/loadavg: 1.53 1.33 1.21 4/49 21237
/proc/meminfo: memFree=828756/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=2.03
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 664 21920 0 18 0 0 188 15 18 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
[pid=21235] ppid=21220 vsize=17804 CPUtime=0.03
/proc/21235/stat : 21235 (clasp) R 21220 21220 2059 34821 2220 4202496 4864 0 18 0 3 0 0 0 18 0 1 0 875998614 18231296 4092 1283457024 134512640 136223643 4290524576 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21235/statm: 4451 4092 174 418 0 4031 0
[pid=21236] ppid=21220 vsize=27096 CPUtime=0.77
/proc/21236/stat : 21236 (gringo) R 21220 21220 2059 34821 2220 4202496 7825 0 23 0 74 3 0 0 18 0 1 0 875998614 27746304 5674 1283457024 134512640 136959103 4294410704 18446744073709551615 134695241 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21236/statm: 6774 5674 256 598 0 6173 0
Current children cumulated CPU time (s) 2.83
Current children cumulated vsize (KiB) 47496

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

[startup+3.20973 s]
/proc/loadavg: 1.53 1.33 1.21 4/49 21237
/proc/meminfo: memFree=828756/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=2.03
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 664 21920 0 18 0 0 188 15 18 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
[pid=21235] ppid=21220 vsize=19256 CPUtime=0.03
/proc/21235/stat : 21235 (clasp) R 21220 21220 2059 34821 2220 4202496 5297 0 18 0 3 0 0 0 18 0 1 0 875998614 19718144 4525 1283457024 134512640 136223643 4290524576 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21235/statm: 4814 4525 174 418 0 4394 0
[pid=21236] ppid=21220 vsize=30132 CPUtime=0.87
/proc/21236/stat : 21236 (gringo) R 21220 21220 2059 34821 2220 4202496 8466 0 23 0 84 3 0 0 18 0 1 0 875998614 30855168 6315 1283457024 134512640 136959103 4294410704 18446744073709551615 134598754 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21236/statm: 7533 6315 256 598 0 6932 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 51984

[startup+4.01055 s]
/proc/loadavg: 1.53 1.33 1.21 3/48 21237
/proc/meminfo: memFree=847868/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=3.33
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 664 34410 0 41 0 0 312 21 18 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
[pid=21235] ppid=21220 vsize=37008 CPUtime=0.41
/proc/21235/stat : 21235 (clasp) R 21220 21220 2059 34821 2220 4202496 10310 0 19 0 38 3 0 0 18 0 1 0 875998614 37896192 8455 1283457024 134512640 136223643 4290524576 18446744073709551615 134878636 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21235/statm: 9252 8455 214 418 0 8832 0
Current children cumulated CPU time (s) 3.74
Current children cumulated vsize (KiB) 39604

[startup+4.81066 s]
/proc/loadavg: 1.53 1.33 1.21 2/47 21237
/proc/meminfo: memFree=863572/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=3.33
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 664 34410 0 41 0 0 312 21 18 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
[pid=21235] ppid=21220 vsize=36464 CPUtime=1.21
/proc/21235/stat : 21235 (clasp) R 21220 21220 2059 34821 2220 4202496 10330 0 19 0 118 3 0 0 19 0 1 0 875998614 37339136 8341 1283457024 134512640 136223643 4290524576 18446744073709551615 134870807 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21235/statm: 9116 8341 223 418 0 8696 0
Current children cumulated CPU time (s) 4.54
Current children cumulated vsize (KiB) 39060

[startup+5.01069 s]
/proc/loadavg: 1.53 1.33 1.21 2/47 21237
/proc/meminfo: memFree=863572/1048576 swapFree=2078744/2097144
[pid=21220] ppid=21219 vsize=2596 CPUtime=3.33
/proc/21220/stat : 21220 (aspcud-paranoid) S 21219 21220 2059 34821 2220 4202496 664 34410 0 41 0 0 312 21 18 0 1 0 875998608 2658304 300 1283457024 134512640 135304128 4287072912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21220/statm: 649 300 253 194 0 35 0
[pid=21235] ppid=21220 vsize=36464 CPUtime=1.41
/proc/21235/stat : 21235 (clasp) R 21220 21220 2059 34821 2220 4202496 10330 0 19 0 138 3 0 0 19 0 1 0 875998614 37339136 8341 1283457024 134512640 136223643 4290524576 18446744073709551615 134650441 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21235/statm: 9116 8341 223 418 0 8696 0
Current children cumulated CPU time (s) 4.74
Current children cumulated vsize (KiB) 39060

Child status: 0
Real time (s): 5.10688
CPU time (s): 4.8243
CPU user time (s): 4.55628
CPU system time (s): 0.268016
CPU usage (%): 94.4666
Max. virtual memory (cumulated for all children) (KiB): 95264

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.55628
system time used= 0.268016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 48994
page faults= 62
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1636
involuntary context switches= 1122

runsolver used 0 second user time and 0 second system time

The end