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: runsolver -s SIGUSR1 -M 1124 -C 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/upgrade/difficult/rand196.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand196.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/upgrade/difficult/rand196.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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.03 0.99 0.97 2/59 21803
/proc/meminfo: memFree=435464/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=1068 CPUtime=0
/proc/21803/stat : 21803 (aspuncud-full) D 21802 21803 1750 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 120646305 1093632 1 18446744073709551615 0 0 140735466085305 4292012336 4151530544 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/21803/statm: 267 1 0 0 0 28 0

[startup+0.157297 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 21803
/proc/meminfo: memFree=435464/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=0.05
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 695 2806 2 7 0 1 2 2 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200328 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 21803
/proc/meminfo: memFree=435464/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=0.05
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 695 2806 2 7 0 1 2 2 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300296 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 21803
/proc/meminfo: memFree=435464/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=0.05
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 695 2806 2 7 0 1 2 2 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700221 s]
/proc/loadavg: 1.03 0.99 0.97 2/59 21803
/proc/meminfo: memFree=435464/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=0.05
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 695 2806 2 7 0 1 2 2 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.03 0.99 0.97 2/61 21816
/proc/meminfo: memFree=401588/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=0.05
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 695 2806 2 7 0 1 2 2 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21816] ppid=21803 vsize=33064 CPUtime=1.35
/proc/21816/stat : 21816 (cudf2lp) R 21803 21803 1750 0 -1 4202496 9536 0 1 0 128 7 0 0 20 0 1 0 120646316 33857536 7803 18446744073709551615 4194304 5690517 140735265633792 140735265631160 4293182 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/21816/statm: 8266 7803 160 366 0 7897 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 42276

[startup+3.10031 s]
/proc/loadavg: 1.03 0.99 0.97 2/61 21816
/proc/meminfo: memFree=369844/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=0.05
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 695 2806 2 7 0 1 2 2 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21816] ppid=21803 vsize=93028 CPUtime=2.92
/proc/21816/stat : 21816 (cudf2lp) R 21803 21803 1750 0 -1 4202496 26394 0 1 0 278 14 0 0 20 0 1 0 120646316 95260672 19667 18446744073709551615 4194304 5690517 140735265633792 140735265630376 4382128 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/21816/statm: 23257 19667 160 366 0 22888 0
Current children cumulated CPU time (s) 2.97
Current children cumulated vsize (KiB) 102240

[startup+6.30029 s]
/proc/loadavg: 1.03 0.99 0.97 2/61 21817
/proc/meminfo: memFree=375672/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=5.02
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 722 42128 2 8 0 1 474 27 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075632 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21817] ppid=21803 vsize=52444 CPUtime=1.13
/proc/21817/stat : 21817 (gringo) R 21803 21803 1750 0 -1 4202496 14596 0 0 0 107 6 0 0 20 0 1 0 120646821 53702656 11463 18446744073709551615 4194304 6531320 140733518140800 140733518137224 4597961 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21817/statm: 13111 11463 278 571 0 12532 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 61656

[startup+12.7003 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273612/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=2.1
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40353 0 0 0 198 12 0 0 20 0 1 0 120647361 142147584 34185 18446744073709551615 4194304 6012874 140737121578784 140737121578104 4548565 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21818/statm: 34704 34185 226 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 12.43
Current children cumulated vsize (KiB) 170072

[startup+25.5004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273612/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=14.8
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40459 0 0 0 1467 13 0 0 20 0 1 0 120647361 142147584 34291 18446744073709551615 4194304 6012874 140737121578784 140737121578104 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21818/statm: 34704 34291 226 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 25.13
Current children cumulated vsize (KiB) 170072

Solver just ended. Dumping a history of the last processes samples

[startup+25.6004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273612/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=14.9
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40459 0 0 0 1477 13 0 0 20 0 1 0 120647361 142147584 34291 18446744073709551615 4194304 6012874 140737121578784 140737121578104 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21818/statm: 34704 34291 226 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 170072

[startup+28.8004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273612/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=18.05
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40459 0 1 0 1792 13 0 0 20 0 1 0 120647361 142147584 34292 18446744073709551615 4194304 6012874 140737121578784 140737121578104 4499263 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21818/statm: 34704 34292 227 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 28.38
Current children cumulated vsize (KiB) 170072

[startup+32.0049 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273488/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=21.23
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40568 0 1 0 2110 13 0 0 20 0 1 0 120647361 142147584 34401 18446744073709551615 4194304 6012874 140737121578784 140737121578104 4497053 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21818/statm: 34704 34401 227 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 31.56
Current children cumulated vsize (KiB) 170072

[startup+33.6004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273240/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=22.81
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40568 0 1 0 2268 13 0 0 20 0 1 0 120647361 142147584 34401 18446744073709551615 4194304 6012874 140737121578784 140737121577848 4546227 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21818/statm: 34704 34401 227 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 33.14
Current children cumulated vsize (KiB) 170072

[startup+34.4004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273240/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=23.6
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40568 0 1 0 2347 13 0 0 20 0 1 0 120647361 142147584 34401 18446744073709551615 4194304 6012874 140737121578784 140737121577848 4494997 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21818/statm: 34704 34401 227 444 0 34252 0
[pid=21819] ppid=21803 vsize=22044 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1322 0 0 0 0 1 0 0 20 0 1 0 120647361 22573056 1131 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 33.93
Current children cumulated vsize (KiB) 170072

[startup+34.6004 s]
/proc/loadavg: 1.02 0.99 0.97 2/62 21819
/proc/meminfo: memFree=273240/1022884 swapFree=0/0
[pid=21803] ppid=21802 vsize=9212 CPUtime=10.32
/proc/21803/stat : 21803 (aspuncud-full) S 21802 21803 1750 0 -1 4202496 761 152363 2 8 0 1 959 72 20 0 1 0 120646305 9433088 365 18446744073709551615 4194304 5129932 140735466076976 140735466075040 140059899688030 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21803/statm: 2303 365 303 229 0 63 0
[pid=21818] ppid=21803 vsize=138816 CPUtime=23.79
/proc/21818/stat : 21818 (unclasp) R 21803 21803 1750 0 -1 4202496 40568 0 1 0 2366 13 0 0 20 0 1 0 120647361 142147584 34401 18446744073709551615 4194304 6012874 140737121578784 140737121578072 5256141 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/21818/statm: 34704 34401 227 444 0 34252 0
[pid=21819] ppid=21803 vsize=22180 CPUtime=0.01
/proc/21819/stat : 21819 (parse.py) S 21803 21803 1750 0 -1 4202496 1336 0 0 0 0 1 0 0 20 0 1 0 120647361 22712320 1145 18446744073709551615 4194304 6642060 140735809889536 140735809887784 140178927896352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21819/statm: 5545 1145 508 598 0 631 0
Current children cumulated CPU time (s) 34.12
Current children cumulated vsize (KiB) 170208

Child status: 0
Real time (s): 34.6888
CPU time (s): 34.2421
CPU user time (s): 33.2781
CPU system time (s): 0.96406
CPU usage (%): 98.7124
Max. virtual memory (cumulated for all children) (KiB): 474116

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 33.2781
system time used= 0.96406
maximum resident set size= 403808
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 195324
page faults= 11
swaps= 0
block input operations= 69128
block output operations= 51096
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 134
involuntary context switches= 4003

runsolver used 0.048003 second user time and 0.16401 second system time

The end