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/caefdef6-3477-11e0-84ef-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//caefdef6-3477-11e0-84ef-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/caefdef6-3477-11e0-84ef-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.01 1.01 1.00 5/36 1076
/proc/meminfo: memFree=628916/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2588 CPUtime=0.01
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 374 0 0 0 1 0 0 0 23 0 1 0 67520152 2650112 279 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/1072/statm: 647 279 234 194 0 34 0
[pid=1073] ppid=1072 vsize=2588 CPUtime=0
/proc/1073/stat : 1073 (aspcud-1.5) S 1072 1072 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 23 0 1 0 67520152 2650112 133 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/1073/statm: 647 133 87 194 0 34 0
[pid=1074] ppid=1073 vsize=2588 CPUtime=0
/proc/1074/stat : 1074 (aspcud-1.5) R 1073 1072 19908 34817 19908 4202560 126 0 0 0 0 0 0 0 25 0 1 0 67520152 2650112 150 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/1074/statm: 647 150 104 194 0 34 0
[pid=1076] ppid=1074 vsize=2588 CPUtime=0
/proc/1076/stat : 1076 (aspcud-1.5) R 1074 1072 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67520152 2650112 46 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/1076/statm: 647 46 0 194 0 34 0

[startup+0.169015 s]
/proc/loadavg: 1.01 1.01 1.00 5/36 1076
/proc/meminfo: memFree=628916/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=0.01
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 1519 0 0 1 0 0 0 25 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.205006 s]
/proc/loadavg: 1.01 1.01 1.00 5/36 1076
/proc/meminfo: memFree=628916/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=0.01
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 1519 0 0 1 0 0 0 25 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305018 s]
/proc/loadavg: 1.01 1.01 1.00 5/36 1076
/proc/meminfo: memFree=628916/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=0.01
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 1519 0 0 1 0 0 0 25 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705049 s]
/proc/loadavg: 1.01 1.01 1.00 5/36 1076
/proc/meminfo: memFree=628916/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=0.01
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 1519 0 0 1 0 0 0 25 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50782 s]
/proc/loadavg: 1.01 1.01 1.00 2/37 1084
/proc/meminfo: memFree=590156/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=0.01
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 1519 0 0 1 0 0 0 25 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=5024 CPUtime=0
/proc/1082/stat : 1082 (clasp) S 1072 1072 19908 34817 19908 4202496 1110 0 0 0 0 0 0 0 18 0 1 0 67520153 5144576 977 1283457024 134512640 136285277 4289692912 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/1082/statm: 1256 977 177 433 0 821 0
[pid=1083] ppid=1072 vsize=7028 CPUtime=0.16
/proc/1083/stat : 1083 (gringo) S 1072 1072 19908 34817 19908 4202496 1702 0 0 0 16 0 0 0 18 0 1 0 67520153 7196672 1196 1283457024 134512640 136933539 4292571184 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/1083/statm: 1757 1196 242 592 0 1162 0
[pid=1084] ppid=1072 vsize=29216 CPUtime=1.15
/proc/1084/stat : 1084 (cudf2lp) R 1072 1072 19908 34817 19908 4202496 9416 0 0 0 110 5 0 0 25 0 1 0 67520153 29917184 7084 1283457024 134512640 135786343 4293038256 18446744073709551615 135191486 0 0 6 0 0 0 0 17 0 0 0 0
/proc/1084/statm: 7304 7084 139 311 0 6991 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 43864

[startup+3.11092 s]
/proc/loadavg: 1.01 1.01 1.00 2/35 1084
/proc/meminfo: memFree=602464/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=13064 CPUtime=1.3
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 3699 0 0 0 130 0 0 0 19 0 1 0 67520153 13377536 3054 1283457024 134512640 136285277 4289692912 18446744073709551615 134733718 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 3266 3054 234 433 0 2831 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 15660

[startup+6.31173 s]
/proc/loadavg: 1.01 1.01 1.00 2/35 1084
/proc/meminfo: memFree=600976/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=15176 CPUtime=4.5
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 4202 0 0 0 450 0 0 0 25 0 1 0 67520153 15540224 3557 1283457024 134512640 136285277 4289692912 18446744073709551615 134686290 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 3794 3557 234 433 0 3359 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 17772

[startup+12.7032 s]
/proc/loadavg: 1.01 1.01 1.00 2/35 1084
/proc/meminfo: memFree=600860/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=15176 CPUtime=10.89
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 4202 0 0 0 1089 0 0 0 25 0 1 0 67520153 15540224 3557 1283457024 134512640 136285277 4289692912 18446744073709551615 134642024 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 3794 3557 234 433 0 3359 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 17772

[startup+25.516 s]
/proc/loadavg: 1.01 1.01 1.00 2/35 1084
/proc/meminfo: memFree=600116/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=15836 CPUtime=23.69
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 4395 0 0 0 2369 0 0 0 25 0 1 0 67520153 16216064 3750 1283457024 134512640 136285277 4289692912 18446744073709551615 134735607 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 3959 3750 234 433 0 3524 0
Current children cumulated CPU time (s) 25.32
Current children cumulated vsize (KiB) 18432

[startup+51.1116 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 1084
/proc/meminfo: memFree=599124/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=16892 CPUtime=49.27
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 4654 0 0 0 4927 0 0 0 25 0 1 0 67520153 17297408 4009 1283457024 134512640 136285277 4289692912 18446744073709551615 134964942 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 4223 4009 234 433 0 3788 0
Current children cumulated CPU time (s) 50.9
Current children cumulated vsize (KiB) 19488

[startup+102.309 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 1088
/proc/meminfo: memFree=597488/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=18364 CPUtime=100.39
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 4999 0 0 0 10037 2 0 0 25 0 1 0 67520153 18804736 4354 1283457024 134512640 136285277 4289692912 18446744073709551615 134959535 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 4591 4354 234 433 0 4156 0
Current children cumulated CPU time (s) 102.02
Current children cumulated vsize (KiB) 20960

[startup+162.305 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 1094
/proc/meminfo: memFree=596000/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=19684 CPUtime=160.35
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 5342 0 0 0 16033 2 0 0 25 0 1 0 67520153 20156416 4697 1283457024 134512640 136285277 4289692912 18446744073709551615 134930686 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 4921 4697 234 433 0 4486 0
Current children cumulated CPU time (s) 161.98
Current children cumulated vsize (KiB) 22280

[startup+222.308 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 1095
/proc/meminfo: memFree=595520/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=20212 CPUtime=220.32
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 5488 0 0 0 22030 2 0 0 25 0 1 0 67520153 20697088 4843 1283457024 134512640 136285277 4289692912 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 5053 4843 234 433 0 4618 0
Current children cumulated CPU time (s) 221.95
Current children cumulated vsize (KiB) 22808

[startup+282.312 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 1095
/proc/meminfo: memFree=594536/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=21308 CPUtime=280.3
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 5998 0 0 0 28028 2 0 0 25 0 1 0 67520153 21819392 5091 1283457024 134512640 136285277 4289692912 18446744073709551615 134955216 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 5327 5091 234 433 0 4892 0
Current children cumulated CPU time (s) 281.93
Current children cumulated vsize (KiB) 23904



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.414 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 1095
/proc/meminfo: memFree=591932/1048576 swapFree=0/0
[pid=1072] ppid=1071 vsize=2596 CPUtime=1.63
/proc/1072/stat : 1072 (aspcud-1.5) S 1071 1072 19908 34817 19908 4202496 581 15661 0 0 1 0 155 7 16 0 1 0 67520152 2658304 298 1283457024 134512640 135304128 4293798096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1072/statm: 649 298 251 194 0 36 0
[pid=1082] ppid=1072 vsize=23820 CPUtime=288.41
/proc/1082/stat : 1082 (clasp) R 1072 1072 19908 34817 19908 4202496 6644 0 0 0 28839 2 0 0 25 0 1 0 67520153 24391680 5737 1283457024 134512640 136285277 4289692912 18446744073709551615 134650517 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1082/statm: 5955 5737 234 433 0 5520 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 26416

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.441
CPU time (s): 290.078
CPU user time (s): 289.974
CPU system time (s): 0.104006
CPU usage (%): 99.8749
Max. virtual memory (cumulated for all children) (KiB): 43864

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.974
system time used= 0.104006
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 26673
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= 561
involuntary context switches= 3928

runsolver used 0 second user time and 0 second system time

The end