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/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/fe523ea6-9b1b-11df-bc37-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: 1.08 1.03 1.01 3/40 7299
/proc/meminfo: memFree=528036/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2592 CPUtime=0
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 18 0 1 0 69267720 2654208 280 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/7296/statm: 648 280 234 194 0 35 0
[pid=7297] ppid=7296 vsize=2592 CPUtime=0
/proc/7297/stat : 7297 (aspcud-1.5) S 7296 7296 19908 34817 19908 4202560 119 0 0 0 0 0 0 0 25 0 1 0 69267720 2654208 134 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/7297/statm: 648 134 87 194 0 35 0
[pid=7298] ppid=7297 vsize=2592 CPUtime=0
/proc/7298/stat : 7298 (aspcud-1.5) R 7297 7296 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 69267720 2654208 151 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/7298/statm: 648 151 104 194 0 35 0
[pid=7299] ppid=7298 vsize=2592 CPUtime=0
/proc/7299/stat : 7299 (aspcud-1.5) R 7298 7296 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 69267720 2654208 47 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/7299/statm: 648 47 0 194 0 35 0

[startup+0.146376 s]
/proc/loadavg: 1.08 1.03 1.01 3/40 7299
/proc/meminfo: memFree=528036/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=0.01
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 1519 0 0 0 1 0 0 25 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.206379 s]
/proc/loadavg: 1.08 1.03 1.01 3/40 7299
/proc/meminfo: memFree=528036/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=0.01
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 1519 0 0 0 1 0 0 25 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.306385 s]
/proc/loadavg: 1.08 1.03 1.01 3/40 7299
/proc/meminfo: memFree=528036/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=0.01
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 1519 0 0 0 1 0 0 25 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.706419 s]
/proc/loadavg: 1.08 1.03 1.01 3/40 7299
/proc/meminfo: memFree=528036/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=0.01
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 1519 0 0 0 1 0 0 25 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.51018 s]
/proc/loadavg: 1.15 1.04 1.01 1/41 7307
/proc/meminfo: memFree=490132/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=0.01
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 1519 0 0 0 1 0 0 25 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=1928 CPUtime=0
/proc/7305/stat : 7305 (clasp) S 7296 7296 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 69267721 1974272 160 1283457024 134512640 136285277 4287636224 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/7305/statm: 482 160 144 433 0 47 0
[pid=7306] ppid=7296 vsize=2584 CPUtime=0
/proc/7306/stat : 7306 (gringo) S 7296 7296 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 69267721 2646016 272 1283457024 134512640 136933539 4290758256 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/7306/statm: 646 272 242 592 0 51 0
[pid=7307] ppid=7296 vsize=35956 CPUtime=1.28
/proc/7307/stat : 7307 (cudf2lp) R 7296 7296 19908 34817 19908 4202496 10135 0 0 0 123 5 0 0 25 0 1 0 69267721 36818944 8382 1283457024 134512640 135786343 4287859648 18446744073709551615 134581917 0 0 6 0 0 0 0 17 0 0 0 0
/proc/7307/statm: 8989 8382 135 311 0 8676 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 43068

[startup+3.11068 s]
/proc/loadavg: 1.15 1.04 1.01 3/40 7307
/proc/meminfo: memFree=488504/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=13860 CPUtime=0.89
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 4007 0 0 0 87 2 0 0 19 0 1 0 69267721 14192640 3255 1283457024 134512640 136285277 4287636224 18446744073709551615 134669897 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 3465 3255 234 433 0 3030 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 16460

[startup+6.31142 s]
/proc/loadavg: 1.15 1.04 1.01 2/39 7307
/proc/meminfo: memFree=482072/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=32224 CPUtime=4.09
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 8563 0 0 0 407 2 0 0 25 0 1 0 69267721 32997376 7811 1283457024 134512640 136285277 4287636224 18446744073709551615 134963519 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 8056 7811 234 433 0 7621 0
Current children cumulated CPU time (s) 6.08
Current children cumulated vsize (KiB) 34824

[startup+12.7066 s]
/proc/loadavg: 1.13 1.04 1.01 2/38 7307
/proc/meminfo: memFree=468564/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=51732 CPUtime=10.51
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 13445 0 0 0 1048 3 0 0 25 0 1 0 69267721 52973568 12693 1283457024 134512640 136285277 4287636224 18446744073709551615 134639147 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 12933 12693 234 433 0 12498 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 54332

[startup+25.5093 s]
/proc/loadavg: 1.11 1.04 1.01 2/38 7307
/proc/meminfo: memFree=447112/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=63824 CPUtime=23.31
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 16415 0 0 0 2328 3 0 0 25 0 1 0 69267721 65355776 15663 1283457024 134512640 136285277 4287636224 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 15956 15663 234 433 0 15521 0
Current children cumulated CPU time (s) 25.3
Current children cumulated vsize (KiB) 66424

[startup+51.1148 s]
/proc/loadavg: 1.07 1.04 1.01 2/38 7307
/proc/meminfo: memFree=447112/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=63824 CPUtime=48.9
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 16417 0 0 0 4887 3 0 0 25 0 1 0 69267721 65355776 15665 1283457024 134512640 136285277 4287636224 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 15956 15665 234 433 0 15521 0
Current children cumulated CPU time (s) 50.89
Current children cumulated vsize (KiB) 66424

[startup+102.305 s]
/proc/loadavg: 1.03 1.03 1.00 2/38 7307
/proc/meminfo: memFree=447112/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=63824 CPUtime=100.06
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 16417 0 0 0 10003 3 0 0 25 0 1 0 69267721 65355776 15665 1283457024 134512640 136285277 4287636224 18446744073709551615 134650424 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 15956 15665 234 433 0 15521 0
Current children cumulated CPU time (s) 102.05
Current children cumulated vsize (KiB) 66424

[startup+162.309 s]
/proc/loadavg: 1.01 1.02 1.00 2/38 7307
/proc/meminfo: memFree=442276/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=68576 CPUtime=160.03
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 17624 0 0 0 16000 3 0 0 25 0 1 0 69267721 70221824 16872 1283457024 134512640 136285277 4287636224 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 17144 16872 234 433 0 16709 0
Current children cumulated CPU time (s) 162.02
Current children cumulated vsize (KiB) 71176

[startup+222.311 s]
/proc/loadavg: 1.00 1.02 1.00 2/38 7307
/proc/meminfo: memFree=442152/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=68576 CPUtime=219.99
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 17624 0 0 0 21995 4 0 0 25 0 1 0 69267721 70221824 16872 1283457024 134512640 136285277 4287636224 18446744073709551615 134960080 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 17144 16872 234 433 0 16709 0
Current children cumulated CPU time (s) 221.98
Current children cumulated vsize (KiB) 71176

[startup+282.304 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 7312
/proc/meminfo: memFree=438780/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=71324 CPUtime=279.95
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 18620 0 0 0 27991 4 0 0 25 0 1 0 69267721 73035776 17570 1283457024 134512640 136285277 4287636224 18446744073709551615 134733718 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 17831 17570 234 433 0 17396 0
Current children cumulated CPU time (s) 281.94
Current children cumulated vsize (KiB) 73924



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.402 s]
/proc/loadavg: 1.00 1.01 1.00 2/40 7313
/proc/meminfo: memFree=438284/1048576 swapFree=0/0
[pid=7296] ppid=7295 vsize=2600 CPUtime=1.99
/proc/7296/stat : 7296 (aspcud-1.5) S 7295 7296 19908 34817 19908 4202496 581 17692 0 0 0 1 190 8 17 0 1 0 69267720 2662400 299 1283457024 134512640 135304128 4291741392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7296/statm: 650 299 251 194 0 37 0
[pid=7305] ppid=7296 vsize=71652 CPUtime=288.03
/proc/7305/stat : 7305 (clasp) R 7296 7296 19908 34817 19908 4202496 19340 0 0 0 28799 4 0 0 25 0 1 0 69267721 73371648 17650 1283457024 134512640 136285277 4287636224 18446744073709551615 134959492 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7305/statm: 17913 17650 234 433 0 17478 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 74252

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.43
CPU time (s): 290.058
CPU user time (s): 289.906
CPU system time (s): 0.152009
CPU usage (%): 99.8719
Max. virtual memory (cumulated for all children) (KiB): 76828

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.906
system time used= 0.152009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 41292
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= 606
involuntary context switches= 3972

runsolver used 0.008 second user time and 0 second system time

The end