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/install/rand83.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand83.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/install/rand83.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

[startup+0 s]
/proc/loadavg: 1.07 1.00 0.98 2/59 5520
/proc/meminfo: memFree=440364/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=3152 CPUtime=0
/proc/5520/stat : 5520 (runsolver) R 5519 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120602407 3227648 32 18446744073709551615 134512640 134586868 4294776464 4294774512 4152116272 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.206691 s]
/proc/loadavg: 1.07 1.00 0.98 2/59 5520
/proc/meminfo: memFree=440364/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=0.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 696 2811 0 0 0 0 2 1 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300317 s]
/proc/loadavg: 1.07 1.00 0.98 2/59 5520
/proc/meminfo: memFree=440364/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=0.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 696 2811 0 0 0 0 2 1 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.400313 s]
/proc/loadavg: 1.07 1.00 0.98 2/59 5520
/proc/meminfo: memFree=440364/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=0.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 696 2811 0 0 0 0 2 1 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700234 s]
/proc/loadavg: 1.07 1.00 0.98 2/59 5520
/proc/meminfo: memFree=440364/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=0.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 696 2811 0 0 0 0 2 1 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.07 1.00 0.98 2/61 5533
/proc/meminfo: memFree=404380/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=0.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 696 2811 0 0 0 0 2 1 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5533] ppid=5520 vsize=33064 CPUtime=1.42
/proc/5533/stat : 5533 (cudf2lp) R 5520 5520 1733 0 -1 4202496 9719 0 0 0 139 3 0 0 20 0 1 0 120602410 33857536 7986 18446744073709551615 4194304 5690517 140736621898208 140736621895848 4382128 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/5533/statm: 8266 7986 160 366 0 7897 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 42276

[startup+3.10032 s]
/proc/loadavg: 1.07 1.00 0.98 2/61 5533
/proc/meminfo: memFree=372636/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=0.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 696 2811 0 0 0 0 2 1 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5533] ppid=5520 vsize=93028 CPUtime=2.99
/proc/5533/stat : 5533 (cudf2lp) R 5520 5520 1733 0 -1 4202496 26490 0 0 0 288 11 0 0 20 0 1 0 120602410 95260672 19763 18446744073709551615 4194304 5690517 140736621898208 140736621895848 4970627 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/5533/statm: 23257 19763 160 366 0 22888 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 1.06 1.00 0.98 2/61 5534
/proc/meminfo: memFree=381688/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=5.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 724 42132 0 0 0 0 481 22 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5534] ppid=5520 vsize=32688 CPUtime=1.16
/proc/5534/stat : 5534 (gringo) R 5520 5520 1733 0 -1 4202496 9272 0 0 0 110 6 0 0 20 0 1 0 120602920 33472512 7164 18446744073709551615 4194304 6531320 140733686455008 140733686451624 5188275 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5534/statm: 8172 7164 259 571 0 7593 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 41900

[startup+12.7003 s]
/proc/loadavg: 1.06 1.00 0.98 3/61 5534
/proc/meminfo: memFree=9764/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=5.03
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 724 42132 0 0 0 0 481 22 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910059536 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5534] ppid=5520 vsize=454920 CPUtime=7.42
/proc/5534/stat : 5534 (gringo) R 5520 5520 1733 0 -1 4202496 108614 0 0 0 694 48 0 0 20 0 1 0 120602920 465838080 99335 18446744073709551615 4194304 6531320 140733686455008 140733686451432 5554418 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5534/statm: 113730 99335 283 571 0 113151 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 464132

[startup+25.5111 s]
/proc/loadavg: 1.04 1.00 0.98 2/62 5536
/proc/meminfo: memFree=291408/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=147980 CPUtime=11.43
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 44903 0 1 0 1129 14 0 0 20 0 1 0 120603800 151531520 36552 18446744073709551615 4194304 6012874 140735358445584 140735358444904 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/5535/statm: 36995 36552 226 444 0 36543 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 25.03
Current children cumulated vsize (KiB) 179236

[startup+51.1004 s]
/proc/loadavg: 1.03 1.00 0.98 2/62 5536
/proc/meminfo: memFree=291408/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=147980 CPUtime=36.76
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 44920 0 1 0 3661 15 0 0 20 0 1 0 120603800 151531520 36569 18446744073709551615 4194304 6012874 140735358445584 140735358444904 4499205 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/5535/statm: 36995 36569 226 444 0 36543 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 50.36
Current children cumulated vsize (KiB) 179236

[startup+102.3 s]
/proc/loadavg: 1.01 1.00 0.98 2/62 5536
/proc/meminfo: memFree=291284/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=147980 CPUtime=87.51
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 45030 0 1 0 8735 16 0 0 20 0 1 0 120603800 151531520 36679 18446744073709551615 4194304 6012874 140735358445584 140735358444904 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/5535/statm: 36995 36679 226 444 0 36543 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 101.11
Current children cumulated vsize (KiB) 179236

[startup+162.3 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 5536
/proc/meminfo: memFree=204236/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=238928 CPUtime=147.02
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 66918 0 2 0 14672 30 0 0 20 0 1 0 120603800 244662272 58568 18446744073709551615 4194304 6012874 140735358445584 140735358444904 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/5535/statm: 59732 58568 227 444 0 59280 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 160.62
Current children cumulated vsize (KiB) 270184

[startup+222.3 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 5536
/proc/meminfo: memFree=136160/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=308984 CPUtime=206.55
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 83692 0 2 0 20618 37 0 0 20 0 1 0 120603800 316399616 75342 18446744073709551615 4194304 6012874 140735358445584 140735358444904 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/5535/statm: 77246 75342 227 444 0 76794 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 220.15
Current children cumulated vsize (KiB) 340240

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 0.98 3/62 5536
/proc/meminfo: memFree=88792/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=361476 CPUtime=266.09
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 95568 0 2 0 26567 42 0 0 20 0 1 0 120603800 370151424 87218 18446744073709551615 4194304 6012874 140735358445584 140735358444904 4855792 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/5535/statm: 90369 87218 227 444 0 89917 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 279.69
Current children cumulated vsize (KiB) 392732



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.8 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 5536
/proc/meminfo: memFree=67836/1022884 swapFree=0/0
[pid=5520] ppid=5519 vsize=9212 CPUtime=13.59
/proc/5520/stat : 5520 (aspuncud-full) S 5519 5520 1733 0 -1 4202496 765 158950 0 0 0 0 1271 88 20 0 1 0 120602407 9433088 364 18446744073709551615 4194304 5129932 140736910060880 140736910058944 139704239903838 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5520/statm: 2303 364 303 229 0 63 0
[pid=5535] ppid=5520 vsize=383936 CPUtime=286.44
/proc/5535/stat : 5535 (unclasp) R 5520 5520 1733 0 -1 4202496 100746 0 2 0 28600 44 0 0 20 0 1 0 120603800 393150464 92396 18446744073709551615 4194304 6012874 140735358445584 140735358444648 4532853 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/5535/statm: 95984 92396 227 444 0 95532 0
[pid=5536] ppid=5520 vsize=22044 CPUtime=0.01
/proc/5536/stat : 5536 (parse.py) S 5520 5520 1733 0 -1 4202496 1323 0 0 0 1 0 0 0 20 0 1 0 120603800 22573056 1132 18446744073709551615 4194304 6642060 140736748538640 140736748536840 139683299067680 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5536/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 415192

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): 302.888
CPU time (s): 300.171
CPU user time (s): 298.787
CPU system time (s): 1.38409
CPU usage (%): 99.1029
Max. virtual memory (cumulated for all children) (KiB): 499860

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.787
system time used= 1.38409
maximum resident set size= 430140
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262086
page faults= 2
swaps= 0
block input operations= 68552
block output operations= 54080
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 75
involuntary context switches= 34258

runsolver used 0.620038 second user time and 1.18007 second system time

The end