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/201108311143/aspcud-1.5/0207e19a-9b1c-11df-af69-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//0207e19a-9b1c-11df-af69-00163e46d37a.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/0207e19a-9b1c-11df-af69-00163e46d37a.cudf.dudf-real.result -sum(installedsize) 

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.99 0.96 0.68 5/38 20102
/proc/meminfo: memFree=882552/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2584 CPUtime=0
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 60825562 2646016 279 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/20100/statm: 646 279 234 194 0 33 0
[pid=20101] ppid=20100 vsize=2584 CPUtime=0
/proc/20101/stat : 20101 (aspcud-1.5) R 20100 20100 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 60825563 2646016 132 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/20101/statm: 646 132 86 194 0 33 0
[pid=20102] ppid=20101 vsize=2584 CPUtime=0
/proc/20102/stat : 20102 (aspcud-1.5) R 20101 20100 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 60825563 2646016 46 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/20102/statm: 646 46 0 194 0 33 0

[startup+0.160806 s]
/proc/loadavg: 0.99 0.96 0.68 5/38 20102
/proc/meminfo: memFree=882552/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=0.01
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 1519 0 0 1 0 0 0 25 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.204809 s]
/proc/loadavg: 0.99 0.96 0.68 5/38 20102
/proc/meminfo: memFree=882552/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=0.01
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 1519 0 0 1 0 0 0 25 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.304822 s]
/proc/loadavg: 0.99 0.96 0.68 5/38 20102
/proc/meminfo: memFree=882552/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=0.01
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 1519 0 0 1 0 0 0 25 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.70679 s]
/proc/loadavg: 0.99 0.96 0.68 5/38 20102
/proc/meminfo: memFree=882552/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=0.01
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 1519 0 0 1 0 0 0 25 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.5049 s]
/proc/loadavg: 0.99 0.96 0.68 2/40 20111
/proc/meminfo: memFree=845204/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=0.01
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 1519 0 0 1 0 0 0 25 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=1924 CPUtime=0
/proc/20109/stat : 20109 (clasp) S 20100 20100 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 60825564 1970176 159 1283457024 134512640 136285277 4292370304 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/20109/statm: 481 159 144 433 0 46 0
[pid=20110] ppid=20100 vsize=2588 CPUtime=0
/proc/20110/stat : 20110 (gringo) S 20100 20100 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 60825564 2650112 272 1283457024 134512640 136933539 4288420912 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/20110/statm: 647 272 242 592 0 52 0
[pid=20111] ppid=20100 vsize=33320 CPUtime=1.23
/proc/20111/stat : 20111 (cudf2lp) R 20100 20100 19908 34817 19908 4202496 9464 0 0 0 118 5 0 0 25 0 1 0 60825564 34119680 7711 1283457024 134512640 135786343 4290170352 18446744073709551615 135219495 0 0 6 0 0 0 0 17 0 0 0 0
/proc/20111/statm: 8330 7711 135 311 0 8017 0
Current children cumulated CPU time (s) 1.24
Current children cumulated vsize (KiB) 40424

[startup+3.10959 s]
/proc/loadavg: 0.99 0.96 0.68 3/39 20111
/proc/meminfo: memFree=844212/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=13860 CPUtime=0.88
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 4007 0 0 0 86 2 0 0 19 0 1 0 60825564 14192640 3255 1283457024 134512640 136285277 4292370304 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 3465 3255 234 433 0 3030 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 16452

[startup+6.31049 s]
/proc/loadavg: 0.99 0.96 0.68 2/38 20111
/proc/meminfo: memFree=836912/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=32224 CPUtime=4.07
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 8563 0 0 0 399 8 0 0 25 0 1 0 60825564 32997376 7811 1283457024 134512640 136285277 4292370304 18446744073709551615 134733755 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 8056 7811 234 433 0 7621 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 34816

[startup+12.712 s]
/proc/loadavg: 0.99 0.96 0.68 2/38 20111
/proc/meminfo: memFree=823156/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=49128 CPUtime=10.47
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 12823 0 0 0 1038 9 0 0 25 0 1 0 60825564 50307072 12071 1283457024 134512640 136285277 4292370304 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 12282 12071 234 433 0 11847 0
Current children cumulated CPU time (s) 12.43
Current children cumulated vsize (KiB) 51720

[startup+25.505 s]
/proc/loadavg: 0.99 0.96 0.69 2/38 20111
/proc/meminfo: memFree=801704/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=63824 CPUtime=23.26
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 16415 0 0 0 2317 9 0 0 25 0 1 0 60825564 65355776 15663 1283457024 134512640 136285277 4292370304 18446744073709551615 134985191 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 15956 15663 234 433 0 15521 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 66416

[startup+51.1106 s]
/proc/loadavg: 0.99 0.96 0.69 2/40 20115
/proc/meminfo: memFree=801556/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=63824 CPUtime=48.85
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 16417 0 0 0 4876 9 0 0 25 0 1 0 60825564 65355776 15665 1283457024 134512640 136285277 4292370304 18446744073709551615 134649474 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 15956 15665 234 433 0 15521 0
Current children cumulated CPU time (s) 50.81
Current children cumulated vsize (KiB) 66416

[startup+102.312 s]
/proc/loadavg: 0.99 0.97 0.71 2/40 20120
/proc/meminfo: memFree=801432/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=63824 CPUtime=100.02
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 16417 0 0 0 9993 9 0 0 25 0 1 0 60825564 65355776 15665 1283457024 134512640 136285277 4292370304 18446744073709551615 134955650 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 15956 15665 234 433 0 15521 0
Current children cumulated CPU time (s) 101.98
Current children cumulated vsize (KiB) 66416

[startup+162.305 s]
/proc/loadavg: 0.99 0.97 0.73 2/39 20122
/proc/meminfo: memFree=796612/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=68576 CPUtime=159.94
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 17624 0 0 0 15984 10 0 0 25 0 1 0 60825564 70221824 16872 1283457024 134512640 136285277 4292370304 18446744073709551615 134960033 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 17144 16872 234 433 0 16709 0
Current children cumulated CPU time (s) 161.9
Current children cumulated vsize (KiB) 71168

[startup+222.309 s]
/proc/loadavg: 0.99 0.97 0.74 2/38 20125
/proc/meminfo: memFree=796376/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=68576 CPUtime=219.9
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 17624 0 0 0 21980 10 0 0 25 0 1 0 60825564 70221824 16872 1283457024 134512640 136285277 4292370304 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 17144 16872 234 433 0 16709 0
Current children cumulated CPU time (s) 221.86
Current children cumulated vsize (KiB) 71168

[startup+282.304 s]
/proc/loadavg: 0.99 0.97 0.75 2/38 20125
/proc/meminfo: memFree=793152/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=71324 CPUtime=279.85
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 18620 0 0 0 27975 10 0 0 25 0 1 0 60825564 73035776 17570 1283457024 134512640 136285277 4292370304 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 17831 17570 234 433 0 17396 0
Current children cumulated CPU time (s) 281.81
Current children cumulated vsize (KiB) 73916



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.507 s]
/proc/loadavg: 0.99 0.97 0.75 2/38 20125
/proc/meminfo: memFree=792780/1048576 swapFree=0/0
[pid=20100] ppid=20099 vsize=2592 CPUtime=1.96
/proc/20100/stat : 20100 (aspcud-1.5) S 20099 20100 19908 34817 19908 4202496 580 17692 0 0 1 0 184 11 17 0 1 0 60825562 2654208 298 1283457024 134512640 135304128 4294621584 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/20100/statm: 648 298 251 194 0 35 0
[pid=20109] ppid=20100 vsize=71652 CPUtime=288.04
/proc/20109/stat : 20109 (clasp) R 20100 20100 19908 34817 19908 4202496 19340 0 0 0 28792 12 0 0 25 0 1 0 60825564 73371648 17650 1283457024 134512640 136285277 4292370304 18446744073709551615 134985101 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/20109/statm: 17913 17650 234 433 0 17478 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 74244

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 290.534
CPU time (s): 290.046
CPU user time (s): 289.786
CPU system time (s): 0.260016
CPU usage (%): 99.8319
Max. virtual memory (cumulated for all children) (KiB): 76820

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.786
system time used= 0.260016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 41293
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= 611
involuntary context switches= 4003

runsolver used 0 second user time and 0 second system time

The end