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/rand192.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand192.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand192.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: 0.00 0.00 0.00 2/37 4791
/proc/meminfo: memFree=321324/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=3016 CPUtime=0
/proc/4791/stat : 4791 (runsolver) D 4790 4791 4778 34817 4778 4202560 72 0 0 0 0 0 0 0 25 0 1 0 9939679 3088384 93 1283457024 134512640 134586868 4288068288 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/4791/statm: 754 93 62 19 0 53 0

[startup+0.174256 s]
/proc/loadavg: 0.00 0.00 0.00 2/37 4791
/proc/meminfo: memFree=321324/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=0
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 2938 0 0 0 0 0 0 25 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.206239 s]
/proc/loadavg: 0.00 0.00 0.00 2/37 4791
/proc/meminfo: memFree=321324/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=0
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 2938 0 0 0 0 0 0 25 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.309413 s]
/proc/loadavg: 0.00 0.00 0.00 2/37 4791
/proc/meminfo: memFree=321324/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=0
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 2938 0 0 0 0 0 0 25 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.706283 s]
/proc/loadavg: 0.00 0.00 0.00 2/37 4791
/proc/meminfo: memFree=321324/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=0
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 2938 0 0 0 0 0 0 25 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50232 s]
/proc/loadavg: 0.00 0.00 0.00 2/41 4808
/proc/meminfo: memFree=290976/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=0
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 2938 0 0 0 0 0 0 25 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
[pid=4806] ppid=4791 vsize=1928 CPUtime=0
/proc/4806/stat : 4806 (clasp) S 4791 4791 4778 34817 4778 4202496 274 0 18 0 0 0 0 0 23 0 1 0 9939681 1974272 160 1283457024 134512640 136285277 4289618528 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/4806/statm: 482 160 144 433 0 47 0
[pid=4807] ppid=4791 vsize=2588 CPUtime=0
/proc/4807/stat : 4807 (gringo) S 4791 4791 4778 34817 4778 4202496 381 0 23 0 0 0 0 0 22 0 1 0 9939681 2650112 272 1283457024 134512640 136933539 4293695040 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4807/statm: 647 272 242 592 0 52 0
[pid=4808] ppid=4791 vsize=25008 CPUtime=1.06
/proc/4808/stat : 4808 (cudf2lp) R 4791 4791 4778 34817 4778 4202496 6997 0 15 0 101 5 0 0 25 0 1 0 9939681 25608192 5414 1283457024 134512640 135786343 4287308592 18446744073709551615 135196019 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4808/statm: 6252 5414 126 311 0 5939 0
Current children cumulated CPU time (s) 1.06
Current children cumulated vsize (KiB) 32116

[startup+3.11082 s]
/proc/loadavg: 0.00 0.00 0.00 2/41 4808
/proc/meminfo: memFree=262408/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=0
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 2938 0 0 0 0 0 0 25 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
[pid=4806] ppid=4791 vsize=9812 CPUtime=0.04
/proc/4806/stat : 4806 (clasp) S 4791 4791 4778 34817 4778 4202496 2477 0 21 0 4 0 0 0 18 0 1 0 9939681 10047488 2162 1283457024 134512640 136285277 4289618528 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/4806/statm: 2453 2162 177 433 0 2018 0
[pid=4807] ppid=4791 vsize=12780 CPUtime=0.41
/proc/4807/stat : 4807 (gringo) S 4791 4791 4778 34817 4778 4202496 3627 0 23 0 38 3 0 0 18 0 1 0 9939681 13086720 2598 1283457024 134512640 136933539 4293695040 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/4807/statm: 3195 2598 242 592 0 2600 0
[pid=4808] ppid=4791 vsize=40944 CPUtime=2.1
/proc/4808/stat : 4808 (cudf2lp) R 4791 4791 4778 34817 4778 4202496 12888 0 15 0 202 8 0 0 25 0 1 0 9939681 41926656 10035 1283457024 134512640 135786343 4287308592 18446744073709551615 135191532 0 0 6 0 0 0 0 17 0 0 0 0
/proc/4808/statm: 10236 10035 138 311 0 9923 0
Current children cumulated CPU time (s) 2.55
Current children cumulated vsize (KiB) 66128

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

[startup+3.21084 s]
/proc/loadavg: 0.00 0.00 0.00 2/41 4808
/proc/meminfo: memFree=262408/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=2.15
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 15829 0 15 0 0 206 9 18 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
[pid=4806] ppid=4791 vsize=10832 CPUtime=0.04
/proc/4806/stat : 4806 (clasp) R 4791 4791 4778 34817 4778 4202496 2840 0 21 0 4 0 0 0 18 0 1 0 9939681 11091968 2343 1283457024 134512640 136285277 4289618528 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4806/statm: 2708 2343 177 433 0 2273 0
[pid=4807] ppid=4791 vsize=18656 CPUtime=0.47
/proc/4807/stat : 4807 (gringo) R 4791 4791 4778 34817 4778 4202496 5301 0 23 0 43 4 0 0 18 0 1 0 9939681 19103744 3373 1283457024 134512640 136933539 4293695040 18446744073709551615 135827766 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4807/statm: 4664 3373 253 592 0 4069 0
Current children cumulated CPU time (s) 2.66
Current children cumulated vsize (KiB) 32080

[startup+4.01108 s]
/proc/loadavg: 0.00 0.00 0.00 3/40 4808
/proc/meminfo: memFree=260568/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=3.21
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 26841 0 38 0 0 305 16 15 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
[pid=4806] ppid=4791 vsize=28108 CPUtime=0.25
/proc/4806/stat : 4806 (clasp) R 4791 4791 4778 34817 4778 4202496 7550 0 21 0 21 4 0 0 18 0 1 0 9939681 28782592 6578 1283457024 134512640 136285277 4289618528 18446744073709551615 135056038 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4806/statm: 7027 6578 189 433 0 6592 0
Current children cumulated CPU time (s) 3.46
Current children cumulated vsize (KiB) 30700

[startup+4.41121 s]
/proc/loadavg: 0.00 0.00 0.00 2/39 4808
/proc/meminfo: memFree=257484/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=3.21
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 26841 0 38 0 0 305 16 15 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
[pid=4806] ppid=4791 vsize=32172 CPUtime=0.65
/proc/4806/stat : 4806 (clasp) R 4791 4791 4778 34817 4778 4202496 9566 0 21 0 59 6 0 0 18 0 1 0 9939681 32944128 7801 1283457024 134512640 136285277 4289618528 18446744073709551615 134580316 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4806/statm: 8043 7801 234 433 0 7608 0
Current children cumulated CPU time (s) 3.86
Current children cumulated vsize (KiB) 34764

[startup+4.61127 s]
/proc/loadavg: 0.00 0.00 0.00 2/39 4808
/proc/meminfo: memFree=257484/1048576 swapFree=0/0
[pid=4791] ppid=4790 vsize=2592 CPUtime=3.21
/proc/4791/stat : 4791 (aspcud-paranoid) S 4790 4791 4778 34817 4778 4202496 650 26841 0 38 0 0 305 16 15 0 1 0 9939679 2654208 298 1283457024 134512640 135304128 4291255952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4791/statm: 648 298 251 194 0 35 0
[pid=4806] ppid=4791 vsize=32172 CPUtime=0.85
/proc/4806/stat : 4806 (clasp) R 4791 4791 4778 34817 4778 4202496 9566 0 21 0 79 6 0 0 18 0 1 0 9939681 32944128 7801 1283457024 134512640 136285277 4289618528 18446744073709551615 134893013 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/4806/statm: 8043 7801 234 433 0 7608 0
Current children cumulated CPU time (s) 4.06
Current children cumulated vsize (KiB) 34764

Child status: 0
Real time (s): 4.6619
CPU time (s): 4.13226
CPU user time (s): 3.88024
CPU system time (s): 0.252015
CPU usage (%): 88.6388
Max. virtual memory (cumulated for all children) (KiB): 66128

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.88024
system time used= 0.252015
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40984
page faults= 59
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1368
involuntary context switches= 1036

runsolver used 0 second user time and 0.004 second system time

The end