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/201108251442/aspcud-paranoid-1.5/rand21.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand21.cudf.dudf-random.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.62 1.18 0.77 3/34 6238
/proc/meminfo: memFree=311228/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2588 CPUtime=0
/proc/6237/stat : 6237 (aspcud-paranoid) R 6236 6237 4778 34817 4778 4202496 367 0 0 0 0 0 0 0 25 0 1 0 10056804 2650112 280 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/6237/statm: 647 280 234 194 0 34 0
[pid=6238] ppid=6237 vsize=2588 CPUtime=0
/proc/6238/stat : 6238 (aspcud-paranoid) R 6237 6237 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10056805 2650112 46 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/6238/statm: 647 46 0 194 0 34 0

[startup+0.104689 s]
/proc/loadavg: 1.62 1.18 0.77 3/34 6238
/proc/meminfo: memFree=311228/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=0.01
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 2942 0 0 0 0 1 0 25 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.204692 s]
/proc/loadavg: 1.62 1.18 0.77 3/34 6238
/proc/meminfo: memFree=311228/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=0.01
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 2942 0 0 0 0 1 0 25 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.304712 s]
/proc/loadavg: 1.62 1.18 0.77 3/34 6238
/proc/meminfo: memFree=311228/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=0.01
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 2942 0 0 0 0 1 0 25 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.704712 s]
/proc/loadavg: 1.62 1.18 0.77 3/34 6238
/proc/meminfo: memFree=311228/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=0.01
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 2942 0 0 0 0 1 0 25 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50477 s]
/proc/loadavg: 1.62 1.18 0.77 2/37 6254
/proc/meminfo: memFree=280200/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=0.01
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 2942 0 0 0 0 1 0 25 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
[pid=6252] ppid=6237 vsize=1924 CPUtime=0
/proc/6252/stat : 6252 (clasp) S 6237 6237 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 10056806 1970176 159 1283457024 134512640 136285277 4288666592 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/6252/statm: 481 159 144 433 0 46 0
[pid=6253] ppid=6237 vsize=2588 CPUtime=0
/proc/6253/stat : 6253 (gringo) S 6237 6237 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10056806 2650112 272 1283457024 134512640 136933539 4294158736 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6253/statm: 647 272 242 592 0 52 0
[pid=6254] ppid=6237 vsize=25004 CPUtime=1.29
/proc/6254/stat : 6254 (cudf2lp) R 6237 6237 4778 34817 4778 4202496 7167 0 0 0 127 2 0 0 25 0 1 0 10056806 25604096 5569 1283457024 134512640 135786343 4287722384 18446744073709551615 134584800 0 0 6 0 0 0 0 17 0 0 0 0
/proc/6254/statm: 6251 5569 126 311 0 5938 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 32112

[startup+3.11005 s]
/proc/loadavg: 1.62 1.18 0.77 2/37 6254
/proc/meminfo: memFree=238692/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=2.21
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 15848 0 0 0 0 215 6 18 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
[pid=6252] ppid=6237 vsize=14808 CPUtime=0.08
/proc/6252/stat : 6252 (clasp) R 6237 6237 4778 34817 4778 4202496 4073 0 0 0 8 0 0 0 18 0 1 0 10056806 15163392 3283 1283457024 134512640 136285277 4288666592 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/6252/statm: 3702 3283 177 433 0 3267 0
[pid=6253] ppid=6237 vsize=22356 CPUtime=0.56
/proc/6253/stat : 6253 (gringo) R 6237 6237 4778 34817 4778 4202496 6407 0 0 0 53 3 0 0 18 0 1 0 10056806 22892544 4456 1283457024 134512640 136933539 4294158736 18446744073709551615 134687712 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6253/statm: 5589 4456 253 592 0 4994 0
Current children cumulated CPU time (s) 2.85
Current children cumulated vsize (KiB) 39760

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

[startup+3.21014 s]
/proc/loadavg: 1.62 1.18 0.77 2/37 6254
/proc/meminfo: memFree=238692/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=2.21
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 15848 0 0 0 0 215 6 18 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
[pid=6252] ppid=6237 vsize=17052 CPUtime=0.08
/proc/6252/stat : 6252 (clasp) R 6237 6237 4778 34817 4778 4202496 4711 0 0 0 8 0 0 0 18 0 1 0 10056806 17461248 3921 1283457024 134512640 136285277 4288666592 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/6252/statm: 4263 3921 177 433 0 3828 0
[pid=6253] ppid=6237 vsize=26772 CPUtime=0.65
/proc/6253/stat : 6253 (gringo) R 6237 6237 4778 34817 4778 4202496 7509 0 0 0 62 3 0 0 18 0 1 0 10056806 27414528 5429 1283457024 134512640 136933539 4294158736 18446744073709551615 136158718 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6253/statm: 6693 5429 253 592 0 6098 0
Current children cumulated CPU time (s) 2.94
Current children cumulated vsize (KiB) 46420

[startup+4.01028 s]
/proc/loadavg: 1.65 1.19 0.78 3/36 6254
/proc/meminfo: memFree=241064/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=3.24
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 26770 0 0 0 0 313 11 15 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
[pid=6252] ppid=6237 vsize=32336 CPUtime=0.52
/proc/6252/stat : 6252 (clasp) R 6237 6237 4778 34817 4778 4202496 9482 0 0 0 50 2 0 0 18 0 1 0 10056806 33112064 7811 1283457024 134512640 136285277 4288666592 18446744073709551615 134896544 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/6252/statm: 8084 7811 218 433 0 7649 0
Current children cumulated CPU time (s) 3.76
Current children cumulated vsize (KiB) 34932

[startup+4.41039 s]
/proc/loadavg: 1.65 1.19 0.78 2/35 6254
/proc/meminfo: memFree=253108/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=3.24
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 26770 0 0 0 0 313 11 15 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
[pid=6252] ppid=6237 vsize=31792 CPUtime=0.92
/proc/6252/stat : 6252 (clasp) R 6237 6237 4778 34817 4778 4202496 9502 0 0 0 90 2 0 0 18 0 1 0 10056806 32555008 7723 1283457024 134512640 136285277 4288666592 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/6252/statm: 7948 7723 234 433 0 7513 0
Current children cumulated CPU time (s) 4.16
Current children cumulated vsize (KiB) 34388

[startup+4.81049 s]
/proc/loadavg: 1.65 1.19 0.78 2/35 6254
/proc/meminfo: memFree=253108/1048576 swapFree=0/0
[pid=6237] ppid=6236 vsize=2596 CPUtime=3.24
/proc/6237/stat : 6237 (aspcud-paranoid) S 6236 6237 4778 34817 4778 4202496 651 26770 0 0 0 0 313 11 15 0 1 0 10056804 2658304 299 1283457024 134512640 135304128 4293574864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6237/statm: 649 299 251 194 0 36 0
[pid=6252] ppid=6237 vsize=27076 CPUtime=1.32
/proc/6252/stat : 6252 (clasp) R 6237 6237 4778 34817 4778 4202496 9510 0 0 0 130 2 0 0 19 0 1 0 10056806 27725824 6552 1283457024 134512640 136285277 4288666592 18446744073709551615 135636301 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/6252/statm: 6769 6552 242 433 0 6334 0
Current children cumulated CPU time (s) 4.56
Current children cumulated vsize (KiB) 29672

Child status: 0
Real time (s): 4.85128
CPU time (s): 4.59629
CPU user time (s): 4.44828
CPU system time (s): 0.148009
CPU usage (%): 94.7438
Max. virtual memory (cumulated for all children) (KiB): 68124

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.44828
system time used= 0.148009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40844
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= 1290
involuntary context switches= 1024

runsolver used 0 second user time and 0 second system time

The end