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/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-real//ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.dudf-real.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.59 1.45 1.32 2/33 26772
/proc/meminfo: memFree=292968/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2512 CPUtime=0
/proc/26772/stat : 26772 (aspcud-paranoid) R 26771 26772 4778 34817 4778 4194304 186 0 0 0 0 0 0 0 25 0 1 0 11220241 2572288 105 1283457024 134512640 135304128 4287003216 18446744073709551615 4159232729 0 0 0 0 0 0 0 17 0 0 0 0
/proc/26772/statm: 628 105 86 194 0 15 0

[startup+0.164842 s]
/proc/loadavg: 1.59 1.45 1.32 2/33 26772
/proc/meminfo: memFree=292968/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=0.01
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 2937 0 0 0 0 0 1 25 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.204843 s]
/proc/loadavg: 1.59 1.45 1.32 2/33 26772
/proc/meminfo: memFree=292968/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=0.01
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 2937 0 0 0 0 0 1 25 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.304851 s]
/proc/loadavg: 1.59 1.45 1.32 2/33 26772
/proc/meminfo: memFree=292968/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=0.01
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 2937 0 0 0 0 0 1 25 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.714312 s]
/proc/loadavg: 1.59 1.45 1.32 2/33 26772
/proc/meminfo: memFree=292968/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=0.01
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 2937 0 0 0 0 0 1 25 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50494 s]
/proc/loadavg: 1.59 1.45 1.32 2/37 26789
/proc/meminfo: memFree=256752/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=0.01
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 2937 0 0 0 0 0 1 25 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
[pid=26787] ppid=26772 vsize=1928 CPUtime=0
/proc/26787/stat : 26787 (clasp) S 26772 26772 4778 34817 4778 4202496 291 0 0 0 0 0 0 0 25 0 1 0 11220242 1974272 159 1283457024 134512640 136285277 4287376032 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/26787/statm: 482 159 144 433 0 47 0
[pid=26788] ppid=26772 vsize=2584 CPUtime=0
/proc/26788/stat : 26788 (gringo) S 26772 26772 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 11220242 2646016 272 1283457024 134512640 136933539 4289996192 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/26788/statm: 646 272 242 592 0 51 0
[pid=26789] ppid=26772 vsize=26252 CPUtime=1.28
/proc/26789/stat : 26789 (cudf2lp) R 26772 26772 4778 34817 4778 4202496 7749 0 0 0 125 3 0 0 25 0 1 0 11220242 26882048 6151 1283457024 134512640 135786343 4289078496 18446744073709551615 134924408 0 0 6 0 0 0 0 17 0 0 0 0
/proc/26789/statm: 6563 6151 126 311 0 6250 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 33356

[startup+3.10575 s]
/proc/loadavg: 1.59 1.45 1.32 2/37 26789
/proc/meminfo: memFree=220904/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=1.88
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 15803 0 0 0 0 182 6 18 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
[pid=26787] ppid=26772 vsize=21064 CPUtime=0.08
/proc/26787/stat : 26787 (clasp) R 26772 26772 4778 34817 4778 4202496 5716 0 0 0 8 0 0 0 18 0 1 0 11220242 21569536 4926 1283457024 134512640 136285277 4287376032 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26787/statm: 5266 4926 177 433 0 4831 0
[pid=26788] ppid=26772 vsize=35084 CPUtime=0.91
/proc/26788/stat : 26788 (gringo) R 26772 26772 4778 34817 4778 4202496 9695 0 0 0 88 3 0 0 18 0 1 0 11220242 35926016 7100 1283457024 134512640 136933539 4289996192 18446744073709551615 134611954 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26788/statm: 8771 7100 253 592 0 8176 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 58740

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

[startup+3.20578 s]
/proc/loadavg: 1.59 1.45 1.32 2/37 26789
/proc/meminfo: memFree=220904/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=1.88
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 15803 0 0 0 0 182 6 18 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
[pid=26787] ppid=26772 vsize=24136 CPUtime=0.09
/proc/26787/stat : 26787 (clasp) R 26772 26772 4778 34817 4778 4202496 6493 0 0 0 9 0 0 0 18 0 1 0 11220242 24715264 5703 1283457024 134512640 136285277 4287376032 18446744073709551615 134839901 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26787/statm: 6034 5703 177 433 0 5599 0
[pid=26788] ppid=26772 vsize=37660 CPUtime=1.01
/proc/26788/stat : 26788 (gringo) R 26772 26772 4778 34817 4778 4202496 10296 0 0 0 97 4 0 0 18 0 1 0 11220242 38563840 7701 1283457024 134512640 136933539 4289996192 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/26788/statm: 9415 7701 253 592 0 8820 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 64388

[startup+4.00605 s]
/proc/loadavg: 1.59 1.45 1.32 2/35 26789
/proc/meminfo: memFree=247092/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=2.98
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 26731 0 0 0 0 288 10 15 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
[pid=26787] ppid=26772 vsize=31824 CPUtime=0.81
/proc/26787/stat : 26787 (clasp) R 26772 26772 4778 34817 4778 4202496 9510 0 0 0 80 1 0 0 18 0 1 0 11220242 32587776 7731 1283457024 134512640 136285277 4287376032 18446744073709551615 134669396 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26787/statm: 7956 7731 234 433 0 7521 0
Current children cumulated CPU time (s) 3.79
Current children cumulated vsize (KiB) 34416

[startup+4.20612 s]
/proc/loadavg: 1.59 1.45 1.32 2/35 26789
/proc/meminfo: memFree=247092/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=2.98
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 26731 0 0 0 0 288 10 15 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
[pid=26787] ppid=26772 vsize=31824 CPUtime=1.01
/proc/26787/stat : 26787 (clasp) R 26772 26772 4778 34817 4778 4202496 9510 0 0 0 100 1 0 0 19 0 1 0 11220242 32587776 7731 1283457024 134512640 136285277 4287376032 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26787/statm: 7956 7731 234 433 0 7521 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 34416

[startup+4.30616 s]
/proc/loadavg: 1.59 1.45 1.32 2/35 26789
/proc/meminfo: memFree=247092/1048576 swapFree=0/0
[pid=26772] ppid=26771 vsize=2592 CPUtime=2.98
/proc/26772/stat : 26772 (aspcud-paranoid) S 26771 26772 4778 34817 4778 4202496 654 26731 0 0 0 0 288 10 15 0 1 0 11220241 2654208 298 1283457024 134512640 135304128 4287003216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/26772/statm: 648 298 251 194 0 35 0
[pid=26787] ppid=26772 vsize=31824 CPUtime=1.11
/proc/26787/stat : 26787 (clasp) R 26772 26772 4778 34817 4778 4202496 9510 0 0 0 110 1 0 0 19 0 1 0 11220242 32587776 7731 1283457024 134512640 136285277 4287376032 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/26787/statm: 7956 7731 234 433 0 7521 0
Current children cumulated CPU time (s) 4.09
Current children cumulated vsize (KiB) 34416

Child status: 0
Real time (s): 4.39511
CPU time (s): 4.18426
CPU user time (s): 4.02825
CPU system time (s): 0.156009
CPU usage (%): 95.2026
Max. virtual memory (cumulated for all children) (KiB): 65824

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.02825
system time used= 0.156009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40837
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= 1264
involuntary context switches= 994

runsolver used 0 second user time and 0 second system time

The end