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/rand179.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand179.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/install/rand179.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.86 0.97 0.97 2/59 21341
/proc/meminfo: memFree=460016/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=1068 CPUtime=0
/proc/21341/stat : 21341 (aspuncud-full) D 21340 21341 1750 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 120620293 1093632 1 18446744073709551615 0 0 140735561006029 140735395613416 4152120368 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/21341/statm: 267 1 0 0 0 28 0

[startup+0.145982 s]
/proc/loadavg: 0.86 0.97 0.97 2/59 21341
/proc/meminfo: memFree=460016/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=0.05
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 693 2809 2 2 0 1 2 2 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200334 s]
/proc/loadavg: 0.86 0.97 0.97 2/59 21341
/proc/meminfo: memFree=460016/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=0.05
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 693 2809 2 2 0 1 2 2 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300341 s]
/proc/loadavg: 0.86 0.97 0.97 2/59 21341
/proc/meminfo: memFree=460016/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=0.05
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 693 2809 2 2 0 1 2 2 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700232 s]
/proc/loadavg: 0.86 0.97 0.97 2/59 21341
/proc/meminfo: memFree=460016/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=0.05
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 693 2809 2 2 0 1 2 2 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50035 s]
/proc/loadavg: 0.86 0.97 0.97 2/61 21354
/proc/meminfo: memFree=426264/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=0.05
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 693 2809 2 2 0 1 2 2 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21354] ppid=21341 vsize=33064 CPUtime=1.39
/proc/21354/stat : 21354 (cudf2lp) R 21341 21341 1750 0 -1 4202496 9574 0 0 0 132 7 0 0 20 0 1 0 120620301 33857536 7841 18446744073709551615 4194304 5690517 140736478267072 140736478264440 4293191 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/21354/statm: 8266 7841 160 366 0 7897 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 42276

[startup+3.10035 s]
/proc/loadavg: 0.87 0.97 0.97 2/61 21354
/proc/meminfo: memFree=394644/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=0.05
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 693 2809 2 2 0 1 2 2 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21354] ppid=21341 vsize=93028 CPUtime=2.94
/proc/21354/stat : 21354 (cudf2lp) R 21341 21341 1750 0 -1 4202496 26604 0 0 0 278 16 0 0 20 0 1 0 120620301 95260672 19877 18446744073709551615 4194304 5690517 140736478267072 140736478264712 4328384 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/21354/statm: 23257 19877 160 366 0 22888 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 102240

[startup+6.30027 s]
/proc/loadavg: 0.87 0.97 0.97 2/61 21355
/proc/meminfo: memFree=376044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=4.35
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 721 42129 2 2 0 1 409 25 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996592 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21355] ppid=21341 vsize=113780 CPUtime=1.76
/proc/21355/stat : 21355 (gringo) R 21341 21341 1750 0 -1 4202496 30207 0 0 0 169 7 0 0 20 0 1 0 120620745 116510720 25025 18446744073709551615 4194304 6531320 140735007997888 140735007994504 4359104 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21355/statm: 28445 25025 281 571 0 27866 0
Current children cumulated CPU time (s) 6.11
Current children cumulated vsize (KiB) 122992

[startup+12.7004 s]
/proc/loadavg: 0.89 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=2.55
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 40996 0 1 0 242 13 0 0 20 0 1 0 120621301 144605184 34795 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4496101 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34795 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 172472

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

[startup+12.8005 s]
/proc/loadavg: 0.89 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=2.65
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 40996 0 1 0 252 13 0 0 20 0 1 0 120621301 144605184 34795 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34795 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 172472

[startup+19.2003 s]
/proc/loadavg: 0.90 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=9
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 41002 0 1 0 887 13 0 0 20 0 1 0 120621301 144605184 34801 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4855853 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34801 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 18.83
Current children cumulated vsize (KiB) 172472

[startup+20.8004 s]
/proc/loadavg: 0.90 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=10.59
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 41002 0 1 0 1046 13 0 0 20 0 1 0 120621301 144605184 34801 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4525886 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34801 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 20.42
Current children cumulated vsize (KiB) 172472

[startup+21.6004 s]
/proc/loadavg: 0.90 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=11.38
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 41003 0 1 0 1125 13 0 0 20 0 1 0 120621301 144605184 34802 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34802 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 21.21
Current children cumulated vsize (KiB) 172472

[startup+22.4004 s]
/proc/loadavg: 0.91 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=12.17
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 41004 0 1 0 1204 13 0 0 20 0 1 0 120621301 144605184 34803 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4548105 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34803 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 22
Current children cumulated vsize (KiB) 172472

[startup+22.6004 s]
/proc/loadavg: 0.91 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=12.37
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 41004 0 1 0 1224 13 0 0 20 0 1 0 120621301 144605184 34803 18446744073709551615 4194304 6012874 140733667552992 140733667552312 4407312 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 34803 226 444 0 34852 0
[pid=21357] ppid=21341 vsize=22044 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1323 0 0 0 2 0 0 0 20 0 1 0 120621301 22573056 1132 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 22.2
Current children cumulated vsize (KiB) 172472

[startup+22.7009 s]
/proc/loadavg: 0.91 0.97 0.97 2/62 21357
/proc/meminfo: memFree=282044/1022884 swapFree=0/0
[pid=21341] ppid=21340 vsize=9212 CPUtime=9.81
/proc/21341/stat : 21341 (aspuncud-full) S 21340 21341 1750 0 -1 4202496 762 154895 2 2 0 1 910 70 20 0 1 0 120620293 9433088 364 18446744073709551615 4194304 5129932 140735560997936 140735560996000 140559834272862 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/21341/statm: 2303 364 303 229 0 63 0
[pid=21356] ppid=21341 vsize=141216 CPUtime=12.47
/proc/21356/stat : 21356 (unclasp) R 21341 21341 1750 0 -1 4202496 41012 0 1 0 1233 14 0 0 20 0 1 0 120621301 144605184 29691 18446744073709551615 4194304 6012874 140733667552992 140733667552392 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 3 0 0
/proc/21356/statm: 35304 29691 234 444 0 34852 0
[pid=21357] ppid=21341 vsize=22196 CPUtime=0.02
/proc/21357/stat : 21357 (parse.py) S 21341 21341 1750 0 -1 4202496 1344 0 0 0 2 0 0 0 20 0 1 0 120621301 22728704 1153 18446744073709551615 4194304 6642060 140735942229008 140735942227208 139858711533344 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21357/statm: 5549 1153 508 598 0 635 0
Current children cumulated CPU time (s) 22.3
Current children cumulated vsize (KiB) 172624

Child status: 0
Real time (s): 22.7442
CPU time (s): 22.3574
CPU user time (s): 21.4533
CPU system time (s): 0.904056
CPU usage (%): 98.2995
Max. virtual memory (cumulated for all children) (KiB): 486532

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 21.4533
system time used= 0.904056
maximum resident set size= 413932
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 198302
page faults= 5
swaps= 0
block input operations= 68856
block output operations= 51912
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 133
involuntary context switches= 2944

runsolver used 0.048003 second user time and 0.092005 second system time

The end