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/upgrade/difficult/rand293.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand293.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand293.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 0.97 0.98 2/64 20308
/proc/meminfo: memFree=439484/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=3152 CPUtime=0
/proc/20308/stat : 20308 (runsolver) R 20307 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120456984 3227648 32 18446744073709551615 134512640 134586868 4290876560 4290874608 4151583792 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 788 32 0 19 0 73 0

[startup+0.186804 s]
/proc/loadavg: 0.87 0.97 0.98 2/64 20308
/proc/meminfo: memFree=439484/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=0.06
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 734 3619 0 2 0 1 3 2 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200351 s]
/proc/loadavg: 0.87 0.97 0.98 2/64 20308
/proc/meminfo: memFree=439484/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=0.06
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 734 3619 0 2 0 1 3 2 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300313 s]
/proc/loadavg: 0.87 0.97 0.98 2/64 20308
/proc/meminfo: memFree=439484/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=0.06
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 734 3619 0 2 0 1 3 2 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700223 s]
/proc/loadavg: 0.87 0.97 0.98 2/64 20308
/proc/meminfo: memFree=439484/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=0.06
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 734 3619 0 2 0 1 3 2 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.87 0.97 0.98 2/66 20324
/proc/meminfo: memFree=404988/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=0.06
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 734 3619 0 2 0 1 3 2 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20324] ppid=20308 vsize=51264 CPUtime=1.41
/proc/20324/stat : 20324 (cudf2lp) R 20308 20308 1745 0 -1 4202496 11802 0 1 0 135 6 0 0 20 0 1 0 120456990 52494336 10070 18446744073709551615 4194304 5690517 140736137495248 140736137491448 4963881 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/20324/statm: 12816 10070 160 366 0 12447 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 60476

[startup+3.10033 s]
/proc/loadavg: 0.87 0.97 0.98 2/66 20324
/proc/meminfo: memFree=372872/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=0.06
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 734 3619 0 2 0 1 3 2 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20324] ppid=20308 vsize=93028 CPUtime=2.99
/proc/20324/stat : 20324 (cudf2lp) R 20308 20308 1745 0 -1 4202496 26533 0 1 0 285 14 0 0 20 0 1 0 120456990 95260672 19807 18446744073709551615 4194304 5690517 140736137495248 140736137492888 4293600 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/20324/statm: 23257 19807 160 366 0 22888 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.88 0.97 0.98 2/66 20325
/proc/meminfo: memFree=380312/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=4.93
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 758 42939 0 3 0 1 460 32 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20325] ppid=20308 vsize=39972 CPUtime=1.28
/proc/20325/stat : 20325 (gringo) R 20308 20308 1745 0 -1 4202496 11231 0 0 0 123 5 0 0 20 0 1 0 120457484 40931328 8098 18446744073709551615 4194304 6531320 140736573240240 140736573236424 4372792 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20325/statm: 9993 8098 259 571 0 9414 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 49184

[startup+12.7003 s]
/proc/loadavg: 0.89 0.97 0.98 2/66 20325
/proc/meminfo: memFree=9140/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=4.93
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 758 42939 0 3 0 1 460 32 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181568256 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20325] ppid=20308 vsize=473352 CPUtime=7.53
/proc/20325/stat : 20325 (gringo) R 20308 20308 1745 0 -1 4202496 112881 0 0 0 706 47 0 0 20 0 1 0 120457484 484712448 102951 18446744073709551615 4194304 6531320 140736573240240 140736573237912 5520829 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20325/statm: 118338 102951 284 571 0 117759 0
Current children cumulated CPU time (s) 12.46
Current children cumulated vsize (KiB) 482564

[startup+25.5004 s]
/proc/loadavg: 0.91 0.97 0.98 2/67 20327
/proc/meminfo: memFree=279016/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=12.28
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 1214 14 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4356208 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.11
Current children cumulated vsize (KiB) 175964

[startup+51.1004 s]
/proc/loadavg: 0.94 0.97 0.98 2/67 20327
/proc/meminfo: memFree=279016/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=37.61
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 3747 14 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 5496730 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.44
Current children cumulated vsize (KiB) 175964

[startup+102.3 s]
/proc/loadavg: 1.15 1.02 1.00 2/67 20327
/proc/meminfo: memFree=278892/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=88.29
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 8813 16 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4406960 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.12
Current children cumulated vsize (KiB) 175964

[startup+162.3 s]
/proc/loadavg: 1.06 1.01 1.00 2/67 20327
/proc/meminfo: memFree=278892/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=147.67
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 14749 18 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.5
Current children cumulated vsize (KiB) 175964

[startup+222.311 s]
/proc/loadavg: 1.02 1.01 1.00 2/67 20327
/proc/meminfo: memFree=278892/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=207.09
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 20691 18 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4586248 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 219.92
Current children cumulated vsize (KiB) 175964

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20327
/proc/meminfo: memFree=278892/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=266.52
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 26632 20 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.35
Current children cumulated vsize (KiB) 175964



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.2 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20327
/proc/meminfo: memFree=278892/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=287.23
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 28703 20 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 175964

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+303.2 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20327
/proc/meminfo: memFree=278892/1022884 swapFree=0/0
[pid=20308] ppid=20307 vsize=9212 CPUtime=12.82
/proc/20308/stat : 20308 (aspcud-full) S 20307 20308 1745 0 -1 4202496 795 155824 0 3 0 1 1188 93 20 0 1 0 120456984 9433088 365 18446744073709551615 4194304 5129932 140737181569600 140737181567664 140627411731550 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20308/statm: 2303 365 303 229 0 63 0
[pid=20326] ppid=20308 vsize=144712 CPUtime=287.23
/proc/20326/stat : 20326 (clasp) R 20308 20308 1745 0 -1 4202496 41897 0 0 0 28703 20 0 0 20 0 1 0 120458290 148185088 35692 18446744073709551615 4194304 6238623 140733383444160 140733383441184 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20326/statm: 36178 35692 264 500 0 35675 0
[pid=20327] ppid=20308 vsize=22040 CPUtime=0.01
/proc/20327/stat : 20327 (parse.py) S 20308 20308 1745 0 -1 4202496 1305 0 13 0 1 0 0 0 20 0 1 0 120458290 22568960 1128 18446744073709551615 4194304 6642060 140734148898304 140734148896664 139803897681696 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/20327/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 175964

Child status: 0
Real time (s): 303.259
CPU time (s): 300.131
CPU user time (s): 298.943
CPU system time (s): 1.18807
CPU usage (%): 98.9684
Max. virtual memory (cumulated for all children) (KiB): 486664

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.943
system time used= 1.18807
maximum resident set size= 414408
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 200136
page faults= 17
swaps= 0
block input operations= 70024
block output operations= 51952
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 98
involuntary context switches= 34389

runsolver used 0.752047 second user time and 1.5441 second system time

The end