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/e599f3fc-360e-11e0-986e-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//e599f3fc-360e-11e0-986e-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/e599f3fc-360e-11e0-986e-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.11 1.06 1.01 5/35 3298
/proc/meminfo: memFree=398300/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2588 CPUtime=0
/proc/3297/stat : 3297 (aspcud-1.5) R 3296 3297 19908 34817 19908 4202496 366 0 0 0 0 0 0 0 25 0 1 0 68625017 2650112 280 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/3297/statm: 647 280 234 194 0 34 0
[pid=3298] ppid=3297 vsize=2588 CPUtime=0
/proc/3298/stat : 3298 (aspcud-1.5) R 3297 3297 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 68625017 2650112 46 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/3298/statm: 647 46 0 194 0 34 0

[startup+0.120901 s]
/proc/loadavg: 1.11 1.06 1.01 5/35 3298
/proc/meminfo: memFree=398300/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=0.02
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 1520 0 0 0 2 0 0 25 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+0.204909 s]
/proc/loadavg: 1.11 1.06 1.01 5/35 3298
/proc/meminfo: memFree=398300/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=0.02
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 1520 0 0 0 2 0 0 25 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+0.304915 s]
/proc/loadavg: 1.11 1.06 1.01 5/35 3298
/proc/meminfo: memFree=398300/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=0.02
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 1520 0 0 0 2 0 0 25 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+0.704944 s]
/proc/loadavg: 1.11 1.06 1.01 5/35 3298
/proc/meminfo: memFree=398300/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=0.02
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 1520 0 0 0 2 0 0 25 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2596

[startup+1.50626 s]
/proc/loadavg: 1.11 1.06 1.01 3/38 3308
/proc/meminfo: memFree=358988/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.11
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 10497 0 0 0 2 104 5 18 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=8488 CPUtime=0.02
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 2157 0 0 0 2 0 0 0 18 0 1 0 68625018 8691712 1820 1283457024 134512640 136285277 4293761232 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 2122 1820 177 433 0 1687 0
[pid=3307] ppid=3297 vsize=13460 CPUtime=0.29
/proc/3307/stat : 3307 (gringo) R 3297 3297 19908 34817 19908 4202496 3266 0 0 0 29 0 0 0 18 0 1 0 68625018 13783040 2503 1283457024 134512640 136933539 4288519248 18446744073709551615 134596490 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3307/statm: 3365 2503 253 592 0 2770 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 24544

[startup+3.10655 s]
/proc/loadavg: 1.11 1.06 1.01 2/36 3308
/proc/meminfo: memFree=374520/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=12692 CPUtime=1.47
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 3543 0 0 0 146 1 0 0 19 0 1 0 68625018 12996608 2954 1283457024 134512640 136285277 4293761232 18446744073709551615 134733820 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 3173 2954 234 433 0 2738 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 15288

[startup+6.30711 s]
/proc/loadavg: 1.10 1.06 1.01 2/36 3308
/proc/meminfo: memFree=374520/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=12692 CPUtime=4.67
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 3543 0 0 0 466 1 0 0 25 0 1 0 68625018 12996608 2954 1283457024 134512640 136285277 4293761232 18446744073709551615 134667741 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 3173 2954 234 433 0 2738 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 15288

[startup+12.7084 s]
/proc/loadavg: 1.09 1.06 1.01 2/36 3308
/proc/meminfo: memFree=373908/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=13880 CPUtime=11.07
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 3831 0 0 0 1106 1 0 0 25 0 1 0 68625018 14213120 3242 1283457024 134512640 136285277 4293761232 18446744073709551615 134667705 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 3470 3242 234 433 0 3035 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 16476

[startup+25.5106 s]
/proc/loadavg: 1.14 1.07 1.01 2/35 3308
/proc/meminfo: memFree=373544/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=15068 CPUtime=23.86
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 4140 0 0 0 2385 1 0 0 25 0 1 0 68625018 15429632 3551 1283457024 134512640 136285277 4293761232 18446744073709551615 134963423 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 3767 3551 234 433 0 3332 0
Current children cumulated CPU time (s) 25.42
Current children cumulated vsize (KiB) 17664

[startup+51.1059 s]
/proc/loadavg: 1.09 1.07 1.01 2/35 3308
/proc/meminfo: memFree=371808/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=15920 CPUtime=49.44
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 4661 0 0 0 4943 1 0 0 25 0 1 0 68625018 16302080 3764 1283457024 134512640 136285277 4293761232 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 3980 3764 234 433 0 3545 0
Current children cumulated CPU time (s) 51
Current children cumulated vsize (KiB) 18516

[startup+102.306 s]
/proc/loadavg: 1.04 1.05 1.01 2/35 3308
/proc/meminfo: memFree=369328/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=18300 CPUtime=100.62
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 5251 0 0 0 10060 2 0 0 25 0 1 0 68625018 18739200 4354 1283457024 134512640 136285277 4293761232 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 4575 4354 234 433 0 4140 0
Current children cumulated CPU time (s) 102.18
Current children cumulated vsize (KiB) 20896

[startup+162.31 s]
/proc/loadavg: 1.01 1.04 1.00 2/35 3308
/proc/meminfo: memFree=369328/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=18300 CPUtime=160.56
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 5251 0 0 0 16054 2 0 0 25 0 1 0 68625018 18739200 4354 1283457024 134512640 136285277 4293761232 18446744073709551615 134959497 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 4575 4354 234 433 0 4140 0
Current children cumulated CPU time (s) 162.12
Current children cumulated vsize (KiB) 20896

[startup+222.312 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 3308
/proc/meminfo: memFree=367096/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=20544 CPUtime=220.52
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 5825 0 0 0 22049 3 0 0 25 0 1 0 68625018 21037056 4928 1283457024 134512640 136285277 4293761232 18446744073709551615 134966758 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 5136 4928 234 433 0 4701 0
Current children cumulated CPU time (s) 222.08
Current children cumulated vsize (KiB) 23140

[startup+282.305 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 3312
/proc/meminfo: memFree=366824/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=20544 CPUtime=280.49
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 5825 0 0 0 28046 3 0 0 25 0 1 0 68625018 21037056 4928 1283457024 134512640 136285277 4293761232 18446744073709551615 134734271 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 5136 4928 234 433 0 4701 0
Current children cumulated CPU time (s) 282.05
Current children cumulated vsize (KiB) 23140



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.307 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 3313
/proc/meminfo: memFree=366824/1048576 swapFree=0/0
[pid=3297] ppid=3296 vsize=2596 CPUtime=1.56
/proc/3297/stat : 3297 (aspcud-1.5) S 3296 3297 19908 34817 19908 4202496 581 15084 0 0 0 2 148 6 17 0 1 0 68625017 2658304 299 1283457024 134512640 135304128 4290840064 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3297/statm: 649 299 251 194 0 36 0
[pid=3306] ppid=3297 vsize=20544 CPUtime=288.48
/proc/3306/stat : 3306 (clasp) R 3297 3297 19908 34817 19908 4202496 5825 0 0 0 28845 3 0 0 25 0 1 0 68625018 21037056 4928 1283457024 134512640 136285277 4293761232 18446744073709551615 134960040 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3306/statm: 5136 4928 234 433 0 4701 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 23140

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.334
CPU time (s): 290.078
CPU user time (s): 289.958
CPU system time (s): 0.120007
CPU usage (%): 99.9117
Max. virtual memory (cumulated for all children) (KiB): 42136

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.958
system time used= 0.120007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25261
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= 521
involuntary context switches= 3888

runsolver used 0 second user time and 0 second system time

The end