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/201108300820/aspuncud-user-1.0/ec32fc68-7254-11e0-8436-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//ec32fc68-7254-11e0-8436-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/ec32fc68-7254-11e0-8436-00163e1e087d.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.02 1.00 2/33 18239
/proc/meminfo: memFree=949424/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=3020 CPUtime=0
/proc/18239/stat : 18239 (runsolver) D 18238 18239 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 59440098 3092480 94 1283457024 134512640 134586868 4294516880 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/18239/statm: 755 94 62 19 0 54 0

[startup+0.143584 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 18239
/proc/meminfo: memFree=949424/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=0
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.207545 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 18239
/proc/meminfo: memFree=949424/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=0
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.30756 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 18239
/proc/meminfo: memFree=949424/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=0
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.709115 s]
/proc/loadavg: 1.00 1.02 1.00 2/33 18239
/proc/meminfo: memFree=949424/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=0
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.5093 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 18250
/proc/meminfo: memFree=922380/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=0
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=4980 CPUtime=0
/proc/18248/stat : 18248 (unclasp) S 18239 18239 2160 34817 2160 4202496 818 0 6 0 0 0 0 0 18 0 1 0 59440103 5099520 689 1283457024 134512640 135121179 4292614912 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/18248/statm: 1245 689 275 149 0 436 0
[pid=18249] ppid=18239 vsize=4980 CPUtime=0.07
/proc/18249/stat : 18249 (gringo) S 18239 18239 2160 34817 2160 4202496 1007 0 23 0 6 1 0 0 18 0 1 0 59440103 5099520 756 1283457024 134512640 137056543 4290088576 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/18249/statm: 1245 756 253 622 0 620 0
[pid=18250] ppid=18239 vsize=29688 CPUtime=1.19
/proc/18250/stat : 18250 (cudf2lp) R 18239 18239 2160 34817 2160 4202496 9629 0 15 0 116 3 0 0 25 0 1 0 59440103 30400512 7213 1283457024 134512640 135786343 4292609552 18446744073709551615 135219511 0 0 6 0 0 0 0 17 0 0 0 0
/proc/18250/statm: 7422 7213 139 311 0 7109 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 42240

[startup+3.10974 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 18250
/proc/meminfo: memFree=891568/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=0
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 1520 0 3 0 0 0 0 25 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=26784 CPUtime=0.08
/proc/18248/stat : 18248 (unclasp) S 18239 18239 2160 34817 2160 4202496 7268 0 6 0 6 2 0 0 18 0 1 0 59440103 27426816 6075 1283457024 134512640 135121179 4292614912 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/18248/statm: 6696 6075 275 149 0 5887 0
[pid=18249] ppid=18239 vsize=36704 CPUtime=1.3
/proc/18249/stat : 18249 (gringo) R 18239 18239 2160 34817 2160 4202496 11451 0 23 0 128 2 0 0 18 0 1 0 59440103 37584896 7317 1283457024 134512640 137056543 4290088576 18446744073709551615 134590028 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18249/statm: 9176 7317 253 622 0 8551 0
[pid=18250] ppid=18239 vsize=29688 CPUtime=1.48
/proc/18250/stat : 18250 (cudf2lp) R 18239 18239 2160 34817 2160 4202496 9629 0 15 0 144 4 0 0 25 0 1 0 59440103 30400512 7213 1283457024 134512640 135786343 4292609552 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/18250/statm: 7422 7213 139 311 0 7109 0
Current children cumulated CPU time (s) 2.86
Current children cumulated vsize (KiB) 95768

[startup+6.31062 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 18250
/proc/meminfo: memFree=881316/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=74848 CPUtime=1.54
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 32471 0 7 0 142 12 0 0 19 0 1 0 59440103 76644352 17308 1283457024 134512640 135121179 4292614912 18446744073709551615 4159321157 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18712 17308 319 149 0 17903 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 77440

[startup+12.7127 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 18250
/proc/meminfo: memFree=875364/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=74852 CPUtime=7.93
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 136413 0 7 0 740 53 0 0 25 0 1 0 59440103 76648448 17313 1283457024 134512640 135121179 4292614912 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18713 17313 319 149 0 17904 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 77444

[startup+25.5075 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 18250
/proc/meminfo: memFree=876480/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=76652 CPUtime=20.73
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 340359 0 7 0 1937 136 0 0 25 0 1 0 59440103 78491648 17769 1283457024 134512640 135121179 4292614912 18446744073709551615 134977770 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 19163 17769 321 149 0 18354 0
Current children cumulated CPU time (s) 25.25
Current children cumulated vsize (KiB) 79244

[startup+51.1056 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 18250
/proc/meminfo: memFree=876356/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=74856 CPUtime=46.31
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 733315 0 7 0 4306 325 0 0 25 0 1 0 59440103 76652544 17332 1283457024 134512640 135121179 4292614912 18446744073709551615 134734473 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18714 17332 321 149 0 17905 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 77448

[startup+102.303 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 18250
/proc/meminfo: memFree=876108/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=74864 CPUtime=97.46
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 1490957 0 7 0 9098 648 0 0 25 0 1 0 59440103 76660736 17361 1283457024 134512640 135121179 4292614912 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18716 17361 321 149 0 17907 0
Current children cumulated CPU time (s) 101.98
Current children cumulated vsize (KiB) 77456

[startup+162.312 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 18250
/proc/meminfo: memFree=874248/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=75112 CPUtime=157.42
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 2347738 0 7 0 14729 1013 0 0 25 0 1 0 59440103 76914688 17387 1283457024 134512640 135121179 4292614912 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18778 17387 321 149 0 17969 0
Current children cumulated CPU time (s) 161.94
Current children cumulated vsize (KiB) 77704

[startup+222.303 s]
/proc/loadavg: 1.07 1.02 1.00 2/35 18250
/proc/meminfo: memFree=874496/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=75116 CPUtime=217.35
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 3179236 0 7 0 20358 1377 0 0 25 0 1 0 59440103 76918784 17410 1283457024 134512640 135121179 4292614912 18446744073709551615 134890955 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18779 17410 321 149 0 17970 0
Current children cumulated CPU time (s) 221.87
Current children cumulated vsize (KiB) 77708

[startup+282.313 s]
/proc/loadavg: 1.02 1.01 1.00 2/37 18256
/proc/meminfo: memFree=875216/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=76940 CPUtime=277.33
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 3998785 0 7 0 26008 1725 0 0 25 0 1 0 59440103 78786560 17512 1283457024 134512640 135121179 4292614912 18446744073709551615 134990446 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 19235 17512 321 149 0 18426 0
Current children cumulated CPU time (s) 281.85
Current children cumulated vsize (KiB) 79532



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.506 s]
/proc/loadavg: 1.10 1.03 1.01 2/37 18259
/proc/meminfo: memFree=874852/1048576 swapFree=0/0
[pid=18239] ppid=18238 vsize=2592 CPUtime=4.52
/proc/18239/stat : 18239 (aspuncud-user-1) S 18238 18239 2160 34817 2160 4202496 567 41023 0 41 0 0 438 14 18 0 1 0 59440098 2654208 297 1283457024 134512640 135304128 4290465152 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18239/statm: 648 297 251 194 0 35 0
[pid=18248] ppid=18239 vsize=75124 CPUtime=285.5
/proc/18248/stat : 18248 (unclasp) R 18239 18239 2160 34817 2160 4202496 4106017 0 7 0 26783 1767 0 0 25 0 1 0 59440103 76926976 17437 1283457024 134512640 135121179 4292614912 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18248/statm: 18781 17437 321 149 0 17972 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 77716

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.547
CPU time (s): 290.05
CPU user time (s): 272.225
CPU system time (s): 17.8251
CPU usage (%): 99.8291
Max. virtual memory (cumulated for all children) (KiB): 163116

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 272.225
system time used= 17.8251
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 4149983
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 5163
involuntary context switches= 7572

runsolver used 0 second user time and 0 second system time

The end