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/deb285a6-db9e-11df-8f4f-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//deb285a6-db9e-11df-8f4f-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/deb285a6-db9e-11df-8f4f-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.00 1.01 1.00 5/34 2613
/proc/meminfo: memFree=463396/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2592 CPUtime=0.01
/proc/2612/stat : 2612 (aspcud-1.5) R 2611 2612 19908 34817 19908 4202496 366 0 0 0 1 0 0 0 25 0 1 0 68275059 2654208 280 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/2612/statm: 648 280 234 194 0 35 0
[pid=2613] ppid=2612 vsize=2592 CPUtime=0
/proc/2613/stat : 2613 (aspcud-1.5) R 2612 2612 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 68275059 2654208 46 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/2613/statm: 648 46 0 194 0 35 0

[startup+0.127396 s]
/proc/loadavg: 1.00 1.01 1.00 5/34 2613
/proc/meminfo: memFree=463396/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=0.01
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 1523 0 0 1 0 0 0 25 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.207403 s]
/proc/loadavg: 1.00 1.01 1.00 5/34 2613
/proc/meminfo: memFree=463396/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=0.01
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 1523 0 0 1 0 0 0 25 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.30741 s]
/proc/loadavg: 1.00 1.01 1.00 5/34 2613
/proc/meminfo: memFree=463396/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=0.01
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 1523 0 0 1 0 0 0 25 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.707475 s]
/proc/loadavg: 1.00 1.01 1.00 5/34 2613
/proc/meminfo: memFree=463396/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=0.01
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 1523 0 0 1 0 0 0 25 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50766 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 2623
/proc/meminfo: memFree=423984/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=0.01
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 1523 0 0 1 0 0 0 25 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=5840 CPUtime=0.04
/proc/2621/stat : 2621 (clasp) S 2612 2612 19908 34817 19908 4202496 1353 0 0 0 4 0 0 0 18 0 1 0 68275061 5980160 1138 1283457024 134512640 136285277 4290706928 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/2621/statm: 1460 1138 177 433 0 1025 0
[pid=2622] ppid=2612 vsize=7440 CPUtime=0.15
/proc/2622/stat : 2622 (gringo) S 2612 2612 19908 34817 19908 4202496 1867 0 0 0 13 2 0 0 18 0 1 0 68275061 7618560 1361 1283457024 134512640 136933539 4289940912 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/2622/statm: 1860 1361 242 592 0 1265 0
[pid=2623] ppid=2612 vsize=27592 CPUtime=1.19
/proc/2623/stat : 2623 (cudf2lp) R 2612 2612 19908 34817 19908 4202496 8941 0 0 0 116 3 0 0 25 0 1 0 68275061 28254208 6667 1283457024 134512640 135786343 4291383072 18446744073709551615 135195341 0 0 6 0 0 0 0 17 0 0 0 0
/proc/2623/statm: 6898 6667 139 311 0 6585 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 43472

[startup+3.10801 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 2623
/proc/meminfo: memFree=435796/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=15332 CPUtime=1.34
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 4425 0 0 0 130 4 0 0 19 0 1 0 68275061 15699968 3622 1283457024 134512640 136285277 4290706928 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 3833 3622 234 433 0 3398 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 17932

[startup+6.30878 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 2623
/proc/meminfo: memFree=420800/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=33828 CPUtime=4.54
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 9040 0 0 0 450 4 0 0 25 0 1 0 68275061 34639872 8237 1283457024 134512640 136285277 4290706928 18446744073709551615 134650953 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 8457 8237 234 433 0 8022 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 36428

[startup+12.7101 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 2623
/proc/meminfo: memFree=373184/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=77032 CPUtime=10.93
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 20482 0 0 0 1083 10 0 0 25 0 1 0 68275061 78880768 18714 1283457024 134512640 136285277 4290706928 18446744073709551615 134650328 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 19258 18714 234 433 0 18823 0
Current children cumulated CPU time (s) 12.6
Current children cumulated vsize (KiB) 79632

[startup+25.5128 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 2623
/proc/meminfo: memFree=373184/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=79272 CPUtime=23.7
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 21273 0 0 0 2360 10 0 0 25 0 1 0 68275061 81174528 19312 1283457024 134512640 136285277 4290706928 18446744073709551615 134963453 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 19818 19312 234 433 0 19383 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 81872

[startup+51.1089 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 2623
/proc/meminfo: memFree=355452/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=97944 CPUtime=49.29
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 25668 0 0 0 4917 12 0 0 25 0 1 0 68275061 100294656 23707 1283457024 134512640 136285277 4290706928 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 24486 23707 234 433 0 24051 0
Current children cumulated CPU time (s) 50.96
Current children cumulated vsize (KiB) 100544

[startup+102.31 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 2623
/proc/meminfo: memFree=355452/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=97944 CPUtime=100.47
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 25668 0 0 0 10035 12 0 0 25 0 1 0 68275061 100294656 23707 1283457024 134512640 136285277 4290706928 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 24486 23707 234 433 0 24051 0
Current children cumulated CPU time (s) 102.14
Current children cumulated vsize (KiB) 100544

[startup+162.315 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 2626
/proc/meminfo: memFree=354064/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=99672 CPUtime=160.43
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 26082 0 0 0 16030 13 0 0 25 0 1 0 68275061 102064128 24121 1283457024 134512640 136285277 4290706928 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 24918 24121 234 433 0 24483 0
Current children cumulated CPU time (s) 162.1
Current children cumulated vsize (KiB) 102272

[startup+222.308 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 2632
/proc/meminfo: memFree=353692/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=99488 CPUtime=220.38
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 28110 0 0 0 22022 16 0 0 25 0 1 0 68275061 101875712 24063 1283457024 134512640 136285277 4290706928 18446744073709551615 134966750 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 24872 24063 234 433 0 24437 0
Current children cumulated CPU time (s) 222.05
Current children cumulated vsize (KiB) 102088

[startup+282.31 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 2634
/proc/meminfo: memFree=353088/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=100344 CPUtime=280.35
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 29060 0 0 0 28019 16 0 0 25 0 1 0 68275061 102752256 24277 1283457024 134512640 136285277 4290706928 18446744073709551615 134639129 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 25086 24277 234 433 0 24651 0
Current children cumulated CPU time (s) 282.02
Current children cumulated vsize (KiB) 102944



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.312 s]
/proc/loadavg: 1.00 1.00 1.00 3/36 2634
/proc/meminfo: memFree=354080/1048576 swapFree=0/0
[pid=2612] ppid=2611 vsize=2600 CPUtime=1.67
/proc/2612/stat : 2612 (aspcud-1.5) S 2611 2612 19908 34817 19908 4202496 581 15598 0 0 2 0 158 7 16 0 1 0 68275059 2662400 299 1283457024 134512640 135304128 4288816144 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2612/statm: 650 299 251 194 0 37 0
[pid=2621] ppid=2612 vsize=98552 CPUtime=288.36
/proc/2621/stat : 2621 (clasp) R 2612 2612 19908 34817 19908 4202496 29636 0 0 0 28819 17 0 0 25 0 1 0 68275061 100917248 23860 1283457024 134512640 136285277 4290706928 18446744073709551615 134959543 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2621/statm: 24638 23860 234 433 0 24203 0
Current children cumulated CPU time (s) 290.03
Current children cumulated vsize (KiB) 101152

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.346
CPU time (s): 290.086
CPU user time (s): 289.814
CPU system time (s): 0.272017
CPU usage (%): 99.9105
Max. virtual memory (cumulated for all children) (KiB): 104520

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.814
system time used= 0.272017
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49637
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= 669
involuntary context switches= 4009

runsolver used 0 second user time and 0 second system time

The end