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/1aabfc32-d491-11df-9a24-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//1aabfc32-d491-11df-9a24-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/1aabfc32-d491-11df-9a24-00163e3d3b7c.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: 1.02 1.05 1.01 4/37 21652
/proc/meminfo: memFree=652964/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2584 CPUtime=0
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 61649742 2646016 279 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/21650/statm: 646 279 234 194 0 33 0
[pid=21651] ppid=21650 vsize=2584 CPUtime=0.01
/proc/21651/stat : 21651 (aspcud-1.5) R 21650 21650 19908 34817 19908 4202560 110 0 0 0 0 1 0 0 25 0 1 0 61649742 2646016 132 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/21651/statm: 646 132 86 194 0 33 0

[startup+0.186268 s]
/proc/loadavg: 1.02 1.05 1.01 4/37 21652
/proc/meminfo: memFree=652964/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=0.01
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 1523 0 0 0 0 0 1 25 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.213383 s]
/proc/loadavg: 1.02 1.05 1.01 4/37 21652
/proc/meminfo: memFree=652964/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=0.01
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 1523 0 0 0 0 0 1 25 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.302271 s]
/proc/loadavg: 1.02 1.05 1.01 4/37 21652
/proc/meminfo: memFree=652964/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=0.01
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 1523 0 0 0 0 0 1 25 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.714287 s]
/proc/loadavg: 1.02 1.05 1.01 4/37 21652
/proc/meminfo: memFree=652964/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=0.01
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 1523 0 0 0 0 0 1 25 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50635 s]
/proc/loadavg: 1.02 1.05 1.01 2/40 21661
/proc/meminfo: memFree=613452/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=0.01
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 1523 0 0 0 0 0 1 25 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=1928 CPUtime=0
/proc/21659/stat : 21659 (clasp) S 21650 21650 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 61649743 1974272 160 1283457024 134512640 136285277 4293242960 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/21659/statm: 482 160 144 433 0 47 0
[pid=21660] ppid=21650 vsize=2584 CPUtime=0
/proc/21660/stat : 21660 (gringo) S 21650 21650 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 61649743 2646016 272 1283457024 134512640 136933539 4289158384 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/21660/statm: 646 272 242 592 0 51 0
[pid=21661] ppid=21650 vsize=27776 CPUtime=1.22
/proc/21661/stat : 21661 (cudf2lp) D 21650 21650 19908 34817 19908 4202496 8111 0 0 0 120 2 0 0 25 0 1 0 61649743 28442624 6464 1283457024 134512640 135786343 4294631984 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/21661/statm: 6944 6464 128 311 0 6631 0
Current children cumulated CPU time (s) 1.23
Current children cumulated vsize (KiB) 34880

[startup+3.11093 s]
/proc/loadavg: 1.02 1.05 1.01 3/39 21661
/proc/meminfo: memFree=629256/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=4832 CPUtime=1.09
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1134 0 0 0 109 0 0 0 19 0 1 0 61649743 4947968 1002 1283457024 134512640 136285277 4293242960 18446744073709551615 134960040 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1208 1002 234 433 0 773 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 7424

[startup+6.3116 s]
/proc/loadavg: 1.02 1.05 1.01 2/38 21661
/proc/meminfo: memFree=627528/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=5500 CPUtime=4.28
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1321 0 0 0 428 0 0 0 25 0 1 0 61649743 5632000 1171 1283457024 134512640 136285277 4293242960 18446744073709551615 134669863 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1375 1171 234 433 0 940 0
Current children cumulated CPU time (s) 5.99
Current children cumulated vsize (KiB) 8092

[startup+12.7129 s]
/proc/loadavg: 1.01 1.04 1.01 2/38 21661
/proc/meminfo: memFree=627404/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=5664 CPUtime=10.68
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1360 0 0 0 1068 0 0 0 25 0 1 0 61649743 5799936 1210 1283457024 134512640 136285277 4293242960 18446744073709551615 134669904 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1416 1210 234 433 0 981 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 8256

[startup+25.5056 s]
/proc/loadavg: 1.01 1.04 1.01 2/38 21661
/proc/meminfo: memFree=626784/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=6284 CPUtime=23.46
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1553 0 0 0 2346 0 0 0 25 0 1 0 61649743 6434816 1356 1283457024 134512640 136285277 4293242960 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1571 1356 234 433 0 1136 0
Current children cumulated CPU time (s) 25.17
Current children cumulated vsize (KiB) 8876

[startup+51.1106 s]
/proc/loadavg: 1.01 1.04 1.00 2/38 21661
/proc/meminfo: memFree=626412/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=6632 CPUtime=49.07
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1654 0 0 0 4907 0 0 0 25 0 1 0 61649743 6791168 1453 1283457024 134512640 136285277 4293242960 18446744073709551615 134686280 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1658 1453 234 433 0 1223 0
Current children cumulated CPU time (s) 50.78
Current children cumulated vsize (KiB) 9224

[startup+102.312 s]
/proc/loadavg: 1.00 1.03 1.00 2/38 21661
/proc/meminfo: memFree=625668/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=7352 CPUtime=100.23
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1877 0 0 0 10023 0 0 0 25 0 1 0 61649743 7528448 1620 1283457024 134512640 136285277 4293242960 18446744073709551615 134963365 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1838 1620 234 433 0 1403 0
Current children cumulated CPU time (s) 101.94
Current children cumulated vsize (KiB) 9944

[startup+162.305 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 21661
/proc/meminfo: memFree=625296/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=7632 CPUtime=160.19
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 1985 0 0 0 16019 0 0 0 25 0 1 0 61649743 7815168 1695 1283457024 134512640 136285277 4293242960 18446744073709551615 134650052 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1908 1695 234 433 0 1473 0
Current children cumulated CPU time (s) 161.9
Current children cumulated vsize (KiB) 10224

[startup+222.308 s]
/proc/loadavg: 1.00 1.02 1.00 2/40 21664
/proc/meminfo: memFree=624900/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=7796 CPUtime=220.15
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 2074 0 0 0 22015 0 0 0 25 0 1 0 61649743 7983104 1744 1283457024 134512640 136285277 4293242960 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1949 1744 234 433 0 1514 0
Current children cumulated CPU time (s) 221.86
Current children cumulated vsize (KiB) 10388

[startup+282.31 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 21670
/proc/meminfo: memFree=624776/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=7932 CPUtime=280.12
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 2175 0 0 0 28012 0 0 0 25 0 1 0 61649743 8122368 1778 1283457024 134512640 136285277 4293242960 18446744073709551615 134735653 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1983 1778 234 433 0 1548 0
Current children cumulated CPU time (s) 281.83
Current children cumulated vsize (KiB) 10524



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.512 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 21671
/proc/meminfo: memFree=624652/1048576 swapFree=0/0
[pid=21650] ppid=21649 vsize=2592 CPUtime=1.71
/proc/21650/stat : 21650 (aspcud-1.5) S 21649 21650 19908 34817 19908 4202496 575 15116 0 0 0 0 166 5 17 0 1 0 61649742 2654208 298 1283457024 134512640 135304128 4291890944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21650/statm: 648 298 251 194 0 35 0
[pid=21659] ppid=21650 vsize=7932 CPUtime=288.32
/proc/21659/stat : 21659 (clasp) R 21650 21650 19908 34817 19908 4202496 2235 0 0 0 28832 0 0 0 25 0 1 0 61649743 8122368 1778 1283457024 134512640 136285277 4293242960 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/21659/statm: 1983 1778 234 433 0 1548 0
Current children cumulated CPU time (s) 290.03
Current children cumulated vsize (KiB) 10524

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.533
CPU time (s): 290.066
CPU user time (s): 290.002
CPU system time (s): 0.064004
CPU usage (%): 99.8394
Max. virtual memory (cumulated for all children) (KiB): 48704

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 290.002
system time used= 0.064004
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 21478
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= 192
involuntary context switches= 3701

runsolver used 0 second user time and 0 second system time

The end