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/aspcud-full-1.7/slowlink/install/rand954.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand954.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/install/rand954.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: 0.87 1.04 1.07 2/64 19144
/proc/meminfo: memFree=414752/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9204 CPUtime=0
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 119981186 9424896 332 18446744073709551615 4194304 5129932 140736923871824 140736923869288 139668096861984 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2301 332 272 229 0 61 0

[startup+0.198048 s]
/proc/loadavg: 0.87 1.04 1.07 2/64 19144
/proc/meminfo: memFree=414752/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=0.04
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 739 3621 0 1 0 0 3 1 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200311 s]
/proc/loadavg: 0.87 1.04 1.07 2/64 19144
/proc/meminfo: memFree=414752/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=0.04
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 739 3621 0 1 0 0 3 1 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300212 s]
/proc/loadavg: 0.87 1.04 1.07 2/64 19144
/proc/meminfo: memFree=414752/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=0.04
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 739 3621 0 1 0 0 3 1 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700221 s]
/proc/loadavg: 0.87 1.04 1.07 2/64 19144
/proc/meminfo: memFree=414752/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=0.04
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 739 3621 0 1 0 0 3 1 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.87 1.04 1.07 2/66 19160
/proc/meminfo: memFree=382372/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=0.04
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 739 3621 0 1 0 0 3 1 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19160] ppid=19144 vsize=29088 CPUtime=1.17
/proc/19160/stat : 19160 (cudf2lp) R 19144 19144 1745 0 -1 4202496 8556 0 0 0 113 4 0 0 20 0 1 0 119981194 29786112 6822 18446744073709551615 4194304 5690517 140736415414400 140736415412040 4293705 0 0 16781316 0 0 0 0 17 0 0 0 22 0 0
/proc/19160/statm: 7272 6822 159 366 0 6903 0
Current children cumulated CPU time (s) 1.21
Current children cumulated vsize (KiB) 38300

[startup+3.10031 s]
/proc/loadavg: 0.87 1.04 1.07 2/66 19160
/proc/meminfo: memFree=351248/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=0.04
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 739 3621 0 1 0 0 3 1 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19160] ppid=19144 vsize=94068 CPUtime=2.74
/proc/19160/stat : 19160 (cudf2lp) R 19144 19144 1745 0 -1 4202496 21640 0 0 0 266 8 0 0 20 0 1 0 119981194 96325632 18241 18446744073709551615 4194304 5690517 140736415414400 140736415410600 4963881 0 0 16781316 0 0 0 0 17 0 0 0 24 0 0
/proc/19160/statm: 23517 18241 160 366 0 23148 0
Current children cumulated CPU time (s) 2.78
Current children cumulated vsize (KiB) 103280

[startup+6.30032 s]
/proc/loadavg: 0.88 1.04 1.07 2/66 19161
/proc/meminfo: memFree=362284/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=4.93
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 765 42942 0 1 0 0 467 26 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19161] ppid=19144 vsize=30392 CPUtime=1.02
/proc/19161/stat : 19161 (gringo) R 19144 19144 1745 0 -1 4202496 8608 0 0 0 98 4 0 0 20 0 1 0 119981712 31121408 6500 18446744073709551615 4194304 6531320 140735816030352 140735816026968 5510986 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19161/statm: 7598 6500 259 571 0 7019 0
Current children cumulated CPU time (s) 5.95
Current children cumulated vsize (KiB) 39604

[startup+12.7003 s]
/proc/loadavg: 0.89 1.04 1.07 2/66 19161
/proc/meminfo: memFree=9712/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=4.93
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 765 42942 0 1 0 0 467 26 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923870480 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19161] ppid=19144 vsize=469760 CPUtime=7.23
/proc/19161/stat : 19161 (gringo) R 19144 19144 1745 0 -1 4202496 111911 0 0 0 681 42 0 0 20 0 1 0 119981712 481034240 102632 18446744073709551615 4194304 6531320 140735816030352 140735816027528 5520807 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19161/statm: 117440 102632 284 571 0 116861 0
Current children cumulated CPU time (s) 12.16
Current children cumulated vsize (KiB) 478972

[startup+25.5004 s]
/proc/loadavg: 0.91 1.03 1.07 2/67 19163
/proc/meminfo: memFree=275724/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=144008 CPUtime=12.08
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 41703 0 0 0 1196 12 0 0 20 0 1 0 119982514 147464192 35507 18446744073709551615 4194304 6238623 140735834901264 140735834898288 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 36002 35507 263 500 0 35499 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.82
Current children cumulated vsize (KiB) 175260

[startup+51.1004 s]
/proc/loadavg: 0.94 1.03 1.06 2/67 19163
/proc/meminfo: memFree=275724/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=144008 CPUtime=37.41
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 41703 0 0 0 3729 12 0 0 20 0 1 0 119982514 147464192 35507 18446744073709551615 4194304 6238623 140735834901264 140735834898288 4302081 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 36002 35507 263 500 0 35499 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.15
Current children cumulated vsize (KiB) 175260

[startup+102.3 s]
/proc/loadavg: 0.97 1.02 1.06 2/67 19163
/proc/meminfo: memFree=275228/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=144008 CPUtime=88.1
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 41791 0 0 0 8798 12 0 0 20 0 1 0 119982514 147464192 35595 18446744073709551615 4194304 6238623 140735834901264 140735834898288 4696928 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 36002 35595 263 500 0 35499 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.84
Current children cumulated vsize (KiB) 175260

[startup+162.3 s]
/proc/loadavg: 1.02 1.03 1.06 2/67 19163
/proc/meminfo: memFree=252660/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=166168 CPUtime=147.53
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 47434 0 0 0 14736 17 0 0 20 0 1 0 119982514 170156032 41238 18446744073709551615 4194304 6238623 140735834901264 140735834898288 4421810 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 41542 41238 263 500 0 41039 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.27
Current children cumulated vsize (KiB) 197420

[startup+222.305 s]
/proc/loadavg: 1.01 1.02 1.05 2/67 19163
/proc/meminfo: memFree=234804/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=184120 CPUtime=206.91
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 51921 0 0 0 20672 19 0 0 20 0 1 0 119982514 188538880 45725 18446744073709551615 4194304 6238623 140735834901264 140735834898288 4687670 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 46030 45725 263 500 0 45527 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 219.65
Current children cumulated vsize (KiB) 215372

[startup+282.3 s]
/proc/loadavg: 1.00 1.02 1.05 2/67 19163
/proc/meminfo: memFree=194132/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=224948 CPUtime=266.28
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 62066 0 0 0 26602 26 0 0 20 0 1 0 119982514 230346752 55870 18446744073709551615 4194304 6238623 140735834901264 140735834898288 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 56237 55870 263 500 0 55734 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.02
Current children cumulated vsize (KiB) 256200



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.5 s]
/proc/loadavg: 1.00 1.01 1.04 2/67 19163
/proc/meminfo: memFree=150484/1022884 swapFree=0/0
[pid=19144] ppid=19143 vsize=9212 CPUtime=12.73
/proc/19144/stat : 19144 (aspcud-full) S 19143 19144 1745 0 -1 4202496 805 154857 0 1 0 0 1194 79 20 0 1 0 119981186 9433088 365 18446744073709551615 4194304 5129932 140736923871824 140736923869888 139668096717918 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19144/statm: 2303 365 303 229 0 63 0
[pid=19162] ppid=19144 vsize=268780 CPUtime=287.28
/proc/19162/stat : 19162 (clasp) R 19144 19144 1745 0 -1 4202496 72973 0 0 0 28694 34 0 0 20 0 1 0 119982514 275230720 66777 18446744073709551615 4194304 6238623 140735834901264 140735834897816 4353271 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19162/statm: 67195 66777 263 500 0 66692 0
[pid=19163] ppid=19144 vsize=22040 CPUtime=0.01
/proc/19163/stat : 19163 (parse.py) S 19144 19144 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 119982514 22568960 1128 18446744073709551615 4194304 6642060 140735130221984 140735130220344 140523066324768 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/19163/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 300032

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): 303.537
CPU time (s): 300.091
CPU user time (s): 298.911
CPU system time (s): 1.18007
CPU usage (%): 98.8645
Max. virtual memory (cumulated for all children) (KiB): 478972

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.911
system time used= 1.18007
maximum resident set size= 410528
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 230262
page faults= 1
swaps= 0
block input operations= 68464
block output operations= 51680
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 100
involuntary context switches= 34302

runsolver used 0.80805 second user time and 1.52409 second system time

The end