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/rand282.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand282.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand282.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.29 1.11 1.03 5/36 9140
/proc/meminfo: memFree=322100/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2588 CPUtime=0
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 372 0 0 0 0 0 0 0 19 0 1 0 10330693 2650112 279 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/9138/statm: 647 279 234 194 0 34 0
[pid=9139] ppid=9138 vsize=2588 CPUtime=0
/proc/9139/stat : 9139 (aspcud-paranoid) R 9138 9138 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10330693 2650112 132 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/9139/statm: 647 132 86 194 0 34 0
[pid=9140] ppid=9139 vsize=2588 CPUtime=0
/proc/9140/stat : 9140 (aspcud-paranoid) R 9139 9138 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10330693 2650112 46 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/9140/statm: 647 46 0 194 0 34 0

[startup+0.134418 s]
/proc/loadavg: 1.29 1.11 1.03 5/36 9140
/proc/meminfo: memFree=322100/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=0.01
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 2940 0 0 0 1 0 0 25 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.208075 s]
/proc/loadavg: 1.29 1.11 1.03 5/36 9140
/proc/meminfo: memFree=322100/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=0.01
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 2940 0 0 0 1 0 0 25 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.302427 s]
/proc/loadavg: 1.29 1.11 1.03 5/36 9140
/proc/meminfo: memFree=322100/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=0.01
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 2940 0 0 0 1 0 0 25 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.702443 s]
/proc/loadavg: 1.29 1.11 1.03 5/36 9140
/proc/meminfo: memFree=322100/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=0.01
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 2940 0 0 0 1 0 0 25 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.5065 s]
/proc/loadavg: 1.29 1.11 1.03 2/38 9155
/proc/meminfo: memFree=282352/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=0.01
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 2940 0 0 0 1 0 0 25 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
[pid=9153] ppid=9138 vsize=1932 CPUtime=0
/proc/9153/stat : 9153 (clasp) S 9138 9138 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10330695 1978368 160 1283457024 134512640 136285277 4289959200 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9153/statm: 483 160 144 433 0 48 0
[pid=9154] ppid=9138 vsize=2588 CPUtime=0
/proc/9154/stat : 9154 (gringo) S 9138 9138 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10330695 2650112 272 1283457024 134512640 136933539 4288742512 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9154/statm: 647 272 242 592 0 52 0
[pid=9155] ppid=9138 vsize=25004 CPUtime=1.3
/proc/9155/stat : 9155 (cudf2lp) R 9138 9138 4778 34817 4778 4202496 7184 0 0 0 128 2 0 0 25 0 1 0 10330695 25604096 5586 1283457024 134512640 135786343 4288910512 18446744073709551615 135196084 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9155/statm: 6251 5586 126 311 0 5938 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 32120

[startup+3.11183 s]
/proc/loadavg: 1.29 1.11 1.03 2/38 9155
/proc/meminfo: memFree=254048/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=2.21
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 15846 0 0 0 1 210 10 18 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
[pid=9153] ppid=9138 vsize=15340 CPUtime=0.05
/proc/9153/stat : 9153 (clasp) R 9138 9138 4778 34817 4778 4202496 4223 0 0 0 4 1 0 0 18 0 1 0 10330695 15708160 3433 1283457024 134512640 136285277 4289959200 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9153/statm: 3835 3433 177 433 0 3400 0
[pid=9154] ppid=9138 vsize=24532 CPUtime=0.6
/proc/9154/stat : 9154 (gringo) R 9138 9138 4778 34817 4778 4202496 6901 0 0 0 60 0 0 0 18 0 1 0 10330695 25120768 4821 1283457024 134512640 136933539 4288742512 18446744073709551615 136204831 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9154/statm: 6133 4821 253 592 0 5538 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 42468

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

[startup+3.21186 s]
/proc/loadavg: 1.29 1.11 1.03 2/38 9155
/proc/meminfo: memFree=254048/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=2.21
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 15846 0 0 0 1 210 10 18 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
[pid=9153] ppid=9138 vsize=18356 CPUtime=0.08
/proc/9153/stat : 9153 (clasp) R 9138 9138 4778 34817 4778 4202496 5028 0 0 0 7 1 0 0 18 0 1 0 10330695 18796544 4238 1283457024 134512640 136285277 4289959200 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9153/statm: 4589 4238 177 433 0 4154 0
[pid=9154] ppid=9138 vsize=27176 CPUtime=0.67
/proc/9154/stat : 9154 (gringo) R 9138 9138 4778 34817 4778 4202496 7651 0 0 0 67 0 0 0 18 0 1 0 10330695 27828224 5571 1283457024 134512640 136933539 4288742512 18446744073709551615 135827795 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9154/statm: 6794 5571 253 592 0 6199 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 48128

[startup+4.01214 s]
/proc/loadavg: 1.29 1.11 1.03 3/37 9155
/proc/meminfo: memFree=251460/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=3.23
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 26794 0 0 0 1 308 14 15 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
[pid=9153] ppid=9138 vsize=32476 CPUtime=0.54
/proc/9153/stat : 9153 (clasp) R 9138 9138 4778 34817 4778 4202496 9521 0 0 0 50 4 0 0 18 0 1 0 10330695 33255424 7848 1283457024 134512640 136285277 4289959200 18446744073709551615 135639705 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9153/statm: 8119 7848 218 433 0 7684 0
Current children cumulated CPU time (s) 3.77
Current children cumulated vsize (KiB) 35072

[startup+4.2122 s]
/proc/loadavg: 1.29 1.11 1.03 3/37 9155
/proc/meminfo: memFree=251460/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=3.23
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 26794 0 0 0 1 308 14 15 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
[pid=9153] ppid=9138 vsize=31932 CPUtime=0.73
/proc/9153/stat : 9153 (clasp) R 9138 9138 4778 34817 4778 4202496 9541 0 0 0 68 5 0 0 18 0 1 0 10330695 32698368 7759 1283457024 134512640 136285277 4289959200 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9153/statm: 7983 7759 234 433 0 7548 0
Current children cumulated CPU time (s) 3.96
Current children cumulated vsize (KiB) 34528

[startup+4.31329 s]
/proc/loadavg: 1.29 1.11 1.03 3/37 9155
/proc/meminfo: memFree=251460/1048576 swapFree=0/0
[pid=9138] ppid=9137 vsize=2596 CPUtime=3.23
/proc/9138/stat : 9138 (aspcud-paranoid) S 9137 9138 4778 34817 4778 4202496 655 26794 0 0 0 1 308 14 15 0 1 0 10330693 2658304 298 1283457024 134512640 135304128 4286814816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9138/statm: 649 298 251 194 0 36 0
[pid=9153] ppid=9138 vsize=19840 CPUtime=0.84
/proc/9153/stat : 9153 (clasp) R 9138 9138 4778 34817 4778 4202496 9549 0 0 0 78 6 0 0 18 0 1 0 10330695 20316160 1687 1283457024 134512640 136285277 4289959200 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9153/statm: 4960 1687 242 433 0 4525 0
Current children cumulated CPU time (s) 4.07
Current children cumulated vsize (KiB) 22436

Child status: 0
Real time (s): 4.34129
CPU time (s): 4.11226
CPU user time (s): 3.88024
CPU system time (s): 0.232014
CPU usage (%): 94.7243
Max. virtual memory (cumulated for all children) (KiB): 65980

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.88024
system time used= 0.232014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40932
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= 1283
involuntary context switches= 1028

runsolver used 0 second user time and 0.008 second system time

The end