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/aspuncud-user-1.0/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /home/misc2010/tmp/201108311143/aspuncud-user-1.0/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.99 0.98 0.99 5/36 3547
/proc/meminfo: memFree=363904/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2588 CPUtime=0
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 18 0 1 0 68770933 2650112 280 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/3544/statm: 647 280 234 194 0 34 0
[pid=3545] ppid=3544 vsize=2588 CPUtime=0
/proc/3545/stat : 3545 (aspuncud-user-1) S 3544 3544 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 18 0 1 0 68770933 2650112 134 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/3545/statm: 647 134 87 194 0 34 0
[pid=3546] ppid=3545 vsize=2588 CPUtime=0
/proc/3546/stat : 3546 (aspuncud-user-1) R 3545 3544 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 68770933 2650112 151 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3546/statm: 647 151 104 194 0 34 0
[pid=3547] ppid=3546 vsize=2588 CPUtime=0
/proc/3547/stat : 3547 (aspuncud-user-1) R 3546 3544 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 68770933 2650112 47 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/3547/statm: 647 47 0 194 0 34 0

[startup+0.144946 s]
/proc/loadavg: 0.99 0.98 0.99 5/36 3547
/proc/meminfo: memFree=363904/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=0
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 1517 0 0 0 0 0 0 25 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.204953 s]
/proc/loadavg: 0.99 0.98 0.99 5/36 3547
/proc/meminfo: memFree=363904/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=0
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 1517 0 0 0 0 0 0 25 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.304972 s]
/proc/loadavg: 0.99 0.98 0.99 5/36 3547
/proc/meminfo: memFree=363904/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=0
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 1517 0 0 0 0 0 0 25 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.705031 s]
/proc/loadavg: 0.99 0.98 0.99 5/36 3547
/proc/meminfo: memFree=363904/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=0
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 1517 0 0 0 0 0 0 25 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.50516 s]
/proc/loadavg: 0.99 0.98 0.99 2/39 3557
/proc/meminfo: memFree=340184/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=0
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 1517 0 0 0 0 0 0 25 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=3444 CPUtime=0
/proc/3553/stat : 3553 (unclasp) S 3544 3544 19908 34817 19908 4202496 407 0 0 0 0 0 0 0 25 0 1 0 68770934 3526656 271 1283457024 134512640 135121179 4294138272 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3553/statm: 861 271 240 149 0 52 0
[pid=3554] ppid=3544 vsize=2688 CPUtime=0
/proc/3554/stat : 3554 (gringo) S 3544 3544 19908 34817 19908 4202496 408 0 0 0 0 0 0 0 25 0 1 0 68770934 2752512 280 1283457024 134512640 137056543 4293501072 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/3554/statm: 672 280 252 622 0 47 0
[pid=3555] ppid=3544 vsize=39428 CPUtime=1.49
/proc/3555/stat : 3555 (cudf2lp) R 3544 3544 19908 34817 19908 4202496 10981 0 0 0 145 4 0 0 25 0 1 0 68770934 40374272 9338 1283457024 134512640 135786343 4291251936 18446744073709551615 134581917 0 0 6 0 0 0 0 17 0 0 0 0
/proc/3555/statm: 9857 9338 135 311 0 9544 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 48152

[startup+3.10573 s]
/proc/loadavg: 0.99 0.98 0.99 3/38 3557
/proc/meminfo: memFree=359180/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=14548 CPUtime=1.34
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 3434 0 0 0 134 0 0 0 19 0 1 0 68770934 14897152 3120 1283457024 134512640 135121179 4294138272 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 3637 3120 323 149 0 2828 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 17140

[startup+6.30685 s]
/proc/loadavg: 0.99 0.98 0.99 2/37 3557
/proc/meminfo: memFree=338728/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=32580 CPUtime=4.53
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 8046 0 0 0 452 1 0 0 25 0 1 0 68770934 33361920 7606 1283457024 134512640 135121179 4294138272 18446744073709551615 134836042 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 8145 7606 323 149 0 7336 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 35172

[startup+12.7097 s]
/proc/loadavg: 0.99 0.98 0.99 2/37 3558
/proc/meminfo: memFree=302280/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=67852 CPUtime=10.94
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 17025 0 0 0 1084 10 0 0 25 0 1 0 68770934 69480448 16397 1283457024 134512640 135121179 4294138272 18446744073709551615 134891748 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 16963 16397 323 149 0 16154 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 70444

[startup+25.5137 s]
/proc/loadavg: 0.99 0.98 0.99 2/37 3559
/proc/meminfo: memFree=247596/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=120176 CPUtime=23.74
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 30336 0 0 0 2360 14 0 0 25 0 1 0 68770934 123060224 29426 1283457024 134512640 135121179 4294138272 18446744073709551615 134734434 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 30044 29426 324 149 0 29235 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 122768

[startup+51.1073 s]
/proc/loadavg: 0.99 0.98 0.99 2/37 3562
/proc/meminfo: memFree=174564/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=194380 CPUtime=49.29
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 49174 0 3 0 4912 17 0 0 25 0 1 0 68770934 199045120 47844 1283457024 134512640 135121179 4294138272 18446744073709551615 134638565 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 48595 47844 329 149 0 47786 0
Current children cumulated CPU time (s) 51.04
Current children cumulated vsize (KiB) 196972

[startup+102.313 s]
/proc/loadavg: 1.07 1.00 0.99 2/36 3566
/proc/meminfo: memFree=66080/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=301776 CPUtime=100.47
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 80589 0 3 0 10022 25 0 0 25 0 1 0 68770934 309018624 74532 1283457024 134512640 135121179 4294138272 18446744073709551615 134839703 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 75444 74532 329 149 0 74635 0
Current children cumulated CPU time (s) 102.22
Current children cumulated vsize (KiB) 304368

[startup+162.304 s]
/proc/loadavg: 1.02 1.00 0.99 2/38 3590
/proc/meminfo: memFree=5632/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=422440 CPUtime=160.14
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 111625 0 3 0 15983 31 0 0 25 0 1 0 68770934 432578560 104349 1283457024 134512640 135121179 4294138272 18446744073709551615 134839703 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 105610 104349 329 149 0 104801 0
Current children cumulated CPU time (s) 161.89
Current children cumulated vsize (KiB) 425032

[startup+222.312 s]
/proc/loadavg: 1.05 1.01 1.00 2/38 3650
/proc/meminfo: memFree=6020/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=520036 CPUtime=219.64
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 135455 0 3 0 21926 38 0 0 25 0 1 0 68770934 532516864 128179 1283457024 134512640 135121179 4294138272 18446744073709551615 134836100 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 130009 128179 329 149 0 129200 0
Current children cumulated CPU time (s) 221.39
Current children cumulated vsize (KiB) 522628

[startup+282.313 s]
/proc/loadavg: 1.06 1.02 1.00 3/38 3704
/proc/meminfo: memFree=5508/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=600180 CPUtime=279.2
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 155116 0 3 0 27874 46 0 0 25 0 1 0 68770934 614584320 147840 1283457024 134512640 135121179 4294138272 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 150045 147840 329 149 0 149236 0
Current children cumulated CPU time (s) 280.95
Current children cumulated vsize (KiB) 602772



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+291.507 s]
/proc/loadavg: 1.13 1.04 1.01 2/38 3712
/proc/meminfo: memFree=5396/1048576 swapFree=0/0
[pid=3544] ppid=3543 vsize=2592 CPUtime=1.75
/proc/3544/stat : 3544 (aspuncud-user-1) S 3543 3544 19908 34817 19908 4202496 574 14494 0 0 0 0 169 6 17 0 1 0 68770933 2654208 298 1283457024 134512640 135304128 4291417712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/3544/statm: 648 298 251 194 0 35 0
[pid=3553] ppid=3544 vsize=611660 CPUtime=288.34
/proc/3553/stat : 3553 (unclasp) R 3544 3544 19908 34817 19908 4202496 158538 0 3 0 28787 47 0 0 25 0 1 0 68770934 626339840 150625 1283457024 134512640 135121179 4294138272 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/3553/statm: 152915 150625 329 149 0 152106 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 614252

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): 291.56
CPU time (s): 290.15
CPU user time (s): 289.57
CPU system time (s): 0.580036
CPU usage (%): 99.5165
Max. virtual memory (cumulated for all children) (KiB): 614252

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.57
system time used= 0.580036
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 176019
page faults= 3
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 125
involuntary context switches= 4882

runsolver used 0 second user time and 0 second system time

The end