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/rand933.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand933.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand933.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.39 1.40 1.26 6/39 23578
/proc/meminfo: memFree=304880/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2588 CPUtime=0
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 374 0 0 0 0 0 0 0 18 0 1 0 11171105 2650112 280 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/23575/statm: 647 280 234 194 0 34 0
[pid=23576] ppid=23575 vsize=2588 CPUtime=0
/proc/23576/stat : 23576 (aspcud-paranoid) S 23575 23575 4778 34817 4778 4202560 118 0 0 0 0 0 0 0 18 0 1 0 11171105 2650112 134 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/23576/statm: 647 134 87 194 0 34 0
[pid=23577] ppid=23576 vsize=2588 CPUtime=0
/proc/23577/stat : 23577 (aspcud-paranoid) R 23576 23575 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 11171105 2650112 151 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/23577/statm: 647 151 104 194 0 34 0
[pid=23578] ppid=23577 vsize=2588 CPUtime=0
/proc/23578/stat : 23578 (aspcud-paranoid) R 23577 23575 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11171105 2650112 47 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/23578/statm: 647 47 0 194 0 34 0

[startup+0.148916 s]
/proc/loadavg: 1.39 1.40 1.26 6/39 23578
/proc/meminfo: memFree=304880/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=0
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 2931 0 0 0 0 0 0 25 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204915 s]
/proc/loadavg: 1.39 1.40 1.26 6/39 23578
/proc/meminfo: memFree=304880/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=0
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 2931 0 0 0 0 0 0 25 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.307311 s]
/proc/loadavg: 1.39 1.40 1.26 6/39 23578
/proc/meminfo: memFree=304880/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=0
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 2931 0 0 0 0 0 0 25 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.711626 s]
/proc/loadavg: 1.39 1.40 1.26 6/39 23578
/proc/meminfo: memFree=304880/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=0
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 2931 0 0 0 0 0 0 25 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50499 s]
/proc/loadavg: 1.36 1.39 1.26 2/40 23592
/proc/meminfo: memFree=267604/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=0
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 2931 0 0 0 0 0 0 25 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
[pid=23590] ppid=23575 vsize=1924 CPUtime=0.01
/proc/23590/stat : 23590 (clasp) S 23575 23575 4778 34817 4778 4202496 292 0 0 0 0 1 0 0 25 0 1 0 11171107 1970176 159 1283457024 134512640 136285277 4292341600 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/23590/statm: 481 159 144 433 0 46 0
[pid=23591] ppid=23575 vsize=2580 CPUtime=0
/proc/23591/stat : 23591 (gringo) S 23575 23575 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 11171107 2641920 271 1283457024 134512640 136933539 4291620656 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/23591/statm: 645 271 242 592 0 50 0
[pid=23592] ppid=23575 vsize=25004 CPUtime=1.26
/proc/23592/stat : 23592 (cudf2lp) R 23575 23575 4778 34817 4778 4202496 7156 0 0 0 124 2 0 0 25 0 1 0 11171107 25604096 5557 1283457024 134512640 135786343 4287480656 18446744073709551615 134924524 0 0 6 0 0 0 0 17 0 0 0 0
/proc/23592/statm: 6251 5557 126 311 0 5938 0
Current children cumulated CPU time (s) 1.27
Current children cumulated vsize (KiB) 32104

[startup+3.11455 s]
/proc/loadavg: 1.36 1.39 1.26 2/40 23592
/proc/meminfo: memFree=233160/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=2.21
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 15838 0 0 0 0 213 8 18 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
[pid=23590] ppid=23575 vsize=13476 CPUtime=0.07
/proc/23590/stat : 23590 (clasp) R 23575 23575 4778 34817 4778 4202496 3598 0 0 0 5 2 0 0 18 0 1 0 11171107 13799424 3079 1283457024 134512640 136285277 4292341600 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23590/statm: 3369 3079 177 433 0 2934 0
[pid=23591] ppid=23575 vsize=21796 CPUtime=0.51
/proc/23591/stat : 23591 (gringo) R 23575 23575 4778 34817 4778 4202496 6158 0 0 0 51 0 0 0 18 0 1 0 11171107 22319104 4239 1283457024 134512640 136933539 4291620656 18446744073709551615 134691818 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23591/statm: 5449 4239 253 592 0 4854 0
Current children cumulated CPU time (s) 2.79
Current children cumulated vsize (KiB) 37868

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

[startup+3.21463 s]
/proc/loadavg: 1.36 1.39 1.26 2/40 23592
/proc/meminfo: memFree=233160/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=2.21
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 15838 0 0 0 0 213 8 18 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
[pid=23590] ppid=23575 vsize=15860 CPUtime=0.08
/proc/23590/stat : 23590 (clasp) R 23575 23575 4778 34817 4778 4202496 4392 0 0 0 6 2 0 0 18 0 1 0 11171107 16240640 3601 1283457024 134512640 136285277 4292341600 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23590/statm: 3965 3601 177 433 0 3530 0
[pid=23591] ppid=23575 vsize=25120 CPUtime=0.6
/proc/23591/stat : 23591 (gringo) R 23575 23575 4778 34817 4778 4202496 7030 0 0 0 59 1 0 0 18 0 1 0 11171107 25722880 4982 1283457024 134512640 136933539 4291620656 18446744073709551615 136204780 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23591/statm: 6280 4982 253 592 0 5685 0
Current children cumulated CPU time (s) 2.89
Current children cumulated vsize (KiB) 43576

[startup+4.01489 s]
/proc/loadavg: 1.36 1.39 1.26 3/39 23594
/proc/meminfo: memFree=238508/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=3.24
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 26719 0 0 0 0 312 12 15 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
[pid=23590] ppid=23575 vsize=32268 CPUtime=0.46
/proc/23590/stat : 23590 (clasp) R 23575 23575 4778 34817 4778 4202496 9443 0 0 0 40 6 0 0 18 0 1 0 11171107 33042432 7771 1283457024 134512640 136285277 4292341600 18446744073709551615 134904174 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23590/statm: 8067 7771 217 433 0 7632 0
Current children cumulated CPU time (s) 3.7
Current children cumulated vsize (KiB) 34864

[startup+4.21496 s]
/proc/loadavg: 1.36 1.39 1.26 3/39 23594
/proc/meminfo: memFree=238508/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2596 CPUtime=3.24
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 659 26719 0 0 0 0 312 12 15 0 1 0 11171105 2658304 299 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 649 299 251 194 0 36 0
[pid=23590] ppid=23575 vsize=31724 CPUtime=0.66
/proc/23590/stat : 23590 (clasp) R 23575 23575 4778 34817 4778 4202496 9465 0 0 0 59 7 0 0 18 0 1 0 11171107 32485376 7694 1283457024 134512640 136285277 4292341600 18446744073709551615 134931519 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23590/statm: 7931 7694 234 433 0 7496 0
Current children cumulated CPU time (s) 3.9
Current children cumulated vsize (KiB) 34320

[startup+4.31497 s]
/proc/loadavg: 1.36 1.39 1.26 3/39 23594
/proc/meminfo: memFree=238508/1048576 swapFree=0/0
[pid=23575] ppid=23574 vsize=2984 CPUtime=3.98
/proc/23575/stat : 23575 (aspcud-paranoid) S 23574 23575 4778 34817 4778 4202496 961 38004 0 0 0 0 378 20 18 0 1 0 11171105 3055616 375 1283457024 134512640 135304128 4289549552 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/23575/statm: 746 375 256 194 0 133 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 2984

Child status: 0
Real time (s): 4.32522
CPU time (s): 4.02825
CPU user time (s): 3.79224
CPU system time (s): 0.236014
CPU usage (%): 93.1339
Max. virtual memory (cumulated for all children) (KiB): 65968

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.79224
system time used= 0.236014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40771
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= 1281
involuntary context switches= 1053

runsolver used 0 second user time and 0 second system time

The end