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/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/e69a0e36-9ef1-11df-9d4a-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.96 1.00 0.99 5/35 3466
/proc/meminfo: memFree=384688/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2588 CPUtime=0
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 68712357 2650112 280 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/3464/statm: 647 280 234 194 0 34 0
[pid=3465] ppid=3464 vsize=2588 CPUtime=0
/proc/3465/stat : 3465 (aspcud-1.5) R 3464 3464 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 68712357 2650112 133 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3465/statm: 647 133 86 194 0 34 0
[pid=3466] ppid=3465 vsize=2588 CPUtime=0
/proc/3466/stat : 3466 (aspcud-1.5) R 3465 3464 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 68712357 2650112 47 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3466/statm: 647 47 0 194 0 34 0

[startup+0.174538 s]
/proc/loadavg: 0.96 1.00 0.99 5/35 3466
/proc/meminfo: memFree=384688/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=0.01
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 1521 0 0 1 0 0 0 25 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.206571 s]
/proc/loadavg: 0.96 1.00 0.99 5/35 3466
/proc/meminfo: memFree=384688/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=0.01
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 1521 0 0 1 0 0 0 25 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.306551 s]
/proc/loadavg: 0.96 1.00 0.99 5/35 3466
/proc/meminfo: memFree=384688/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=0.01
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 1521 0 0 1 0 0 0 25 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.706581 s]
/proc/loadavg: 0.96 1.00 0.99 5/35 3466
/proc/meminfo: memFree=384688/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=0.01
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 1521 0 0 1 0 0 0 25 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.51401 s]
/proc/loadavg: 0.96 1.00 0.99 2/37 3475
/proc/meminfo: memFree=346164/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=0.01
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 1521 0 0 1 0 0 0 25 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=1924 CPUtime=0
/proc/3473/stat : 3473 (clasp) S 3464 3464 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 68712358 1970176 159 1283457024 134512640 136285277 4293554336 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/3473/statm: 481 159 144 433 0 46 0
[pid=3474] ppid=3464 vsize=2580 CPUtime=0
/proc/3474/stat : 3474 (gringo) S 3464 3464 19908 34817 19908 4202496 403 0 0 0 0 0 0 0 25 0 1 0 68712358 2641920 271 1283457024 134512640 136933539 4294451696 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3474/statm: 645 271 242 592 0 50 0
[pid=3475] ppid=3464 vsize=35864 CPUtime=1.32
/proc/3475/stat : 3475 (cudf2lp) R 3464 3464 19908 34817 19908 4202496 10097 0 0 0 131 1 0 0 25 0 1 0 68712358 36724736 8450 1283457024 134512640 135786343 4289580384 18446744073709551615 135199427 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3475/statm: 8966 8450 135 311 0 8653 0
Current children cumulated CPU time (s) 1.33
Current children cumulated vsize (KiB) 42964

[startup+3.10431 s]
/proc/loadavg: 0.96 1.00 0.99 3/36 3475
/proc/meminfo: memFree=362180/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=4828 CPUtime=1.21
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1121 0 0 0 121 0 0 0 19 0 1 0 68712358 4943872 984 1283457024 134512640 136285277 4293554336 18446744073709551615 134931352 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 1207 984 234 433 0 772 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 7424

[startup+6.30492 s]
/proc/loadavg: 0.97 1.00 0.99 2/35 3475
/proc/meminfo: memFree=361080/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=5176 CPUtime=4.41
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1203 0 0 0 441 0 0 0 25 0 1 0 68712358 5300224 1066 1283457024 134512640 136285277 4293554336 18446744073709551615 134930686 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 1294 1066 234 433 0 859 0
Current children cumulated CPU time (s) 6.1
Current children cumulated vsize (KiB) 7772

[startup+12.7064 s]
/proc/loadavg: 0.97 1.00 0.99 2/35 3475
/proc/meminfo: memFree=360336/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=5776 CPUtime=10.81
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1361 0 0 0 1080 1 0 0 25 0 1 0 68712358 5914624 1224 1283457024 134512640 136285277 4293554336 18446744073709551615 134959492 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 1444 1224 234 433 0 1009 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 8372

[startup+25.5083 s]
/proc/loadavg: 0.97 1.00 0.99 2/35 3475
/proc/meminfo: memFree=359840/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=6284 CPUtime=23.61
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1512 0 0 0 2360 1 0 0 25 0 1 0 68712358 6434816 1352 1283457024 134512640 136285277 4293554336 18446744073709551615 134733718 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 1571 1352 234 433 0 1136 0
Current children cumulated CPU time (s) 25.3
Current children cumulated vsize (KiB) 8880

[startup+51.1027 s]
/proc/loadavg: 0.98 1.00 0.99 2/35 3475
/proc/meminfo: memFree=359096/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=7080 CPUtime=49.2
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1712 0 0 0 4919 1 0 0 25 0 1 0 68712358 7249920 1545 1283457024 134512640 136285277 4293554336 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 1770 1545 234 433 0 1335 0
Current children cumulated CPU time (s) 50.89
Current children cumulated vsize (KiB) 9676

[startup+102.313 s]
/proc/loadavg: 0.99 1.00 0.99 2/35 3475
/proc/meminfo: memFree=358600/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=7476 CPUtime=100.39
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1826 0 0 0 10038 1 0 0 25 0 1 0 68712358 7655424 1659 1283457024 134512640 136285277 4293554336 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 1869 1659 234 433 0 1434 0
Current children cumulated CPU time (s) 102.08
Current children cumulated vsize (KiB) 10072

[startup+162.31 s]
/proc/loadavg: 0.99 1.00 0.99 2/35 3475
/proc/meminfo: memFree=357980/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=8112 CPUtime=160.31
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 1960 0 0 0 16029 2 0 0 25 0 1 0 68712358 8306688 1793 1283457024 134512640 136285277 4293554336 18446744073709551615 134955205 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 2028 1793 234 433 0 1593 0
Current children cumulated CPU time (s) 162
Current children cumulated vsize (KiB) 10708

[startup+222.305 s]
/proc/loadavg: 0.99 1.00 0.99 2/37 3480
/proc/meminfo: memFree=357336/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=8416 CPUtime=220.26
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 2080 0 0 0 22022 4 0 0 25 0 1 0 68712358 8617984 1896 1283457024 134512640 136285277 4293554336 18446744073709551615 134615022 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 2104 1896 234 433 0 1669 0
Current children cumulated CPU time (s) 221.95
Current children cumulated vsize (KiB) 11012

[startup+282.307 s]
/proc/loadavg: 0.99 1.00 0.99 2/37 3486
/proc/meminfo: memFree=356964/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=8804 CPUtime=280.19
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 2165 0 0 0 28015 4 0 0 25 0 1 0 68712358 9015296 1981 1283457024 134512640 136285277 4293554336 18446744073709551615 134736818 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 2201 1981 234 433 0 1766 0
Current children cumulated CPU time (s) 281.88
Current children cumulated vsize (KiB) 11400



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.509 s]
/proc/loadavg: 0.99 1.00 0.99 2/36 3486
/proc/meminfo: memFree=356980/1048576 swapFree=0/0
[pid=3464] ppid=3463 vsize=2596 CPUtime=1.69
/proc/3464/stat : 3464 (aspcud-1.5) S 3463 3464 19908 34817 19908 4202496 576 14716 0 0 1 0 164 4 17 0 1 0 68712357 2658304 299 1283457024 134512640 135304128 4292607920 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3464/statm: 649 299 251 194 0 36 0
[pid=3473] ppid=3464 vsize=8804 CPUtime=288.39
/proc/3473/stat : 3473 (clasp) R 3464 3464 19908 34817 19908 4202496 2165 0 0 0 28835 4 0 0 25 0 1 0 68712358 9015296 1981 1283457024 134512640 136285277 4293554336 18446744073709551615 134733727 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/3473/statm: 2201 1981 234 433 0 1766 0
Current children cumulated CPU time (s) 290.08
Current children cumulated vsize (KiB) 11400

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.529
CPU time (s): 290.122
CPU user time (s): 290.026
CPU system time (s): 0.096006
CPU usage (%): 99.8599
Max. virtual memory (cumulated for all children) (KiB): 48376

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 290.026
system time used= 0.096006
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 20997
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= 191
involuntary context switches= 3686

runsolver used 0 second user time and 0.008 second system time

The end