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/rand992.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand992.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand992.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.53 1.43 1.29 5/37 24124
/proc/meminfo: memFree=304400/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2588 CPUtime=0
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 373 0 0 0 0 0 0 0 18 0 1 0 11180407 2650112 280 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/24121/statm: 647 280 234 194 0 34 0
[pid=24122] ppid=24121 vsize=2588 CPUtime=0
/proc/24122/stat : 24122 (aspcud-paranoid) S 24121 24121 4778 34817 4778 4202560 118 0 0 0 0 0 0 0 18 0 1 0 11180407 2650112 134 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/24122/statm: 647 134 87 194 0 34 0
[pid=24123] ppid=24122 vsize=2588 CPUtime=0
/proc/24123/stat : 24123 (aspcud-paranoid) R 24122 24121 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 11180407 2650112 151 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/24123/statm: 647 151 104 194 0 34 0
[pid=24124] ppid=24123 vsize=2588 CPUtime=0
/proc/24124/stat : 24124 (aspcud-paranoid) R 24123 24121 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11180407 2650112 47 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/24124/statm: 647 47 0 194 0 34 0

[startup+0.180813 s]
/proc/loadavg: 1.53 1.43 1.29 5/37 24124
/proc/meminfo: memFree=304400/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=0
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 2939 0 0 0 0 0 0 25 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204804 s]
/proc/loadavg: 1.53 1.43 1.29 5/37 24124
/proc/meminfo: memFree=304400/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=0
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 2939 0 0 0 0 0 0 25 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.304817 s]
/proc/loadavg: 1.53 1.43 1.29 5/37 24124
/proc/meminfo: memFree=304400/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=0
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 2939 0 0 0 0 0 0 25 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.70484 s]
/proc/loadavg: 1.53 1.43 1.29 5/37 24124
/proc/meminfo: memFree=304400/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=0
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 2939 0 0 0 0 0 0 25 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51006 s]
/proc/loadavg: 1.53 1.43 1.29 2/38 24138
/proc/meminfo: memFree=267140/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=0
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 2939 0 0 0 0 0 0 25 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
[pid=24136] ppid=24121 vsize=1924 CPUtime=0
/proc/24136/stat : 24136 (clasp) S 24121 24121 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 11180408 1970176 159 1283457024 134512640 136285277 4288396192 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/24136/statm: 481 159 144 433 0 46 0
[pid=24137] ppid=24121 vsize=2584 CPUtime=0
/proc/24137/stat : 24137 (gringo) S 24121 24121 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 11180408 2646016 272 1283457024 134512640 136933539 4286786192 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/24137/statm: 646 272 242 592 0 51 0
[pid=24138] ppid=24121 vsize=25000 CPUtime=1.33
/proc/24138/stat : 24138 (cudf2lp) R 24121 24121 4778 34817 4778 4202496 7200 0 0 0 130 3 0 0 25 0 1 0 11180408 25600000 5602 1283457024 134512640 135786343 4288076768 18446744073709551615 134566155 0 0 6 0 0 0 0 17 0 0 0 0
/proc/24138/statm: 6250 5602 126 311 0 5937 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 32104

[startup+3.11056 s]
/proc/loadavg: 1.53 1.43 1.29 2/38 24138
/proc/meminfo: memFree=236724/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=2.19
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 15844 0 0 0 0 214 5 18 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
[pid=24136] ppid=24121 vsize=15732 CPUtime=0.06
/proc/24136/stat : 24136 (clasp) R 24121 24121 4778 34817 4778 4202496 4345 0 0 0 4 2 0 0 18 0 1 0 11180408 16109568 3555 1283457024 134512640 136285277 4288396192 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24136/statm: 3933 3555 177 433 0 3498 0
[pid=24137] ppid=24121 vsize=24692 CPUtime=0.61
/proc/24137/stat : 24137 (gringo) R 24121 24121 4778 34817 4778 4202496 6965 0 0 0 59 2 0 0 18 0 1 0 11180408 25284608 4885 1283457024 134512640 136933539 4286786192 18446744073709551615 134741081 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24137/statm: 6173 4885 253 592 0 5578 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 43020

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

[startup+3.21059 s]
/proc/loadavg: 1.53 1.43 1.29 2/38 24138
/proc/meminfo: memFree=236724/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=2.19
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 15844 0 0 0 0 214 5 18 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
[pid=24136] ppid=24121 vsize=18632 CPUtime=0.06
/proc/24136/stat : 24136 (clasp) R 24121 24121 4778 34817 4778 4202496 5094 0 0 0 4 2 0 0 18 0 1 0 11180408 19079168 4304 1283457024 134512640 136285277 4288396192 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24136/statm: 4658 4304 177 433 0 4223 0
[pid=24137] ppid=24121 vsize=28196 CPUtime=0.71
/proc/24137/stat : 24137 (gringo) R 24121 24121 4778 34817 4778 4202496 7858 0 0 0 69 2 0 0 18 0 1 0 11180408 28872704 5778 1283457024 134512640 136933539 4286786192 18446744073709551615 136192633 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24137/statm: 7049 5778 253 592 0 6454 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 49424

[startup+4.0112 s]
/proc/loadavg: 1.56 1.44 1.29 3/37 24138
/proc/meminfo: memFree=234012/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=3.27
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 26816 0 0 0 0 318 9 15 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
[pid=24136] ppid=24121 vsize=32236 CPUtime=0.49
/proc/24136/stat : 24136 (clasp) R 24121 24121 4778 34817 4778 4202496 9431 0 0 0 47 2 0 0 18 0 1 0 11180408 33009664 7754 1283457024 134512640 136285277 4288396192 18446744073709551615 134638699 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24136/statm: 8059 7754 220 433 0 7624 0
Current children cumulated CPU time (s) 3.76
Current children cumulated vsize (KiB) 34832

[startup+4.21165 s]
/proc/loadavg: 1.56 1.44 1.29 3/37 24138
/proc/meminfo: memFree=234012/1048576 swapFree=0/0
[pid=24121] ppid=24120 vsize=2596 CPUtime=3.27
/proc/24121/stat : 24121 (aspcud-paranoid) S 24120 24121 4778 34817 4778 4202496 658 26816 0 0 0 0 318 9 15 0 1 0 11180407 2658304 299 1283457024 134512640 135304128 4294369680 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24121/statm: 649 299 251 194 0 36 0
[pid=24136] ppid=24121 vsize=26944 CPUtime=0.68
/proc/24136/stat : 24136 (clasp) R 24121 24121 4778 34817 4778 4202496 9459 0 0 0 66 2 0 0 18 0 1 0 11180408 27590656 6504 1283457024 134512640 136285277 4288396192 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24136/statm: 6736 6504 242 433 0 6301 0
Current children cumulated CPU time (s) 3.95
Current children cumulated vsize (KiB) 29540

Child status: 0
Real time (s): 4.25038
CPU time (s): 4.00825
CPU user time (s): 3.87224
CPU system time (s): 0.136008
CPU usage (%): 94.3034
Max. virtual memory (cumulated for all children) (KiB): 65968

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

runsolver used 0 second user time and 0.012 second system time

The end