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/easy/rand414.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand414.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand414.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.99 2/64 20248
/proc/meminfo: memFree=284748/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9204 CPUtime=0
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 120392691 9424896 332 18446744073709551615 4194304 5129932 140733251743664 140733251741128 140268750653216 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2301 332 272 229 0 61 0

[startup+0.116348 s]
/proc/loadavg: 0.86 0.97 0.99 2/64 20248
/proc/meminfo: memFree=284748/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=0.04
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 735 3616 0 0 0 0 2 2 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200352 s]
/proc/loadavg: 0.86 0.97 0.99 2/64 20248
/proc/meminfo: memFree=284748/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=0.04
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 735 3616 0 0 0 0 2 2 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300328 s]
/proc/loadavg: 0.86 0.97 0.99 2/64 20248
/proc/meminfo: memFree=284748/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=0.04
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 735 3616 0 0 0 0 2 2 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700226 s]
/proc/loadavg: 0.86 0.97 0.99 2/64 20248
/proc/meminfo: memFree=284748/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=0.04
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 735 3616 0 0 0 0 2 2 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.87 0.97 0.99 2/66 20264
/proc/meminfo: memFree=250376/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=0.04
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 735 3616 0 0 0 0 2 2 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20264] ppid=20248 vsize=48864 CPUtime=1.43
/proc/20264/stat : 20264 (cudf2lp) R 20248 20248 1745 0 -1 4202496 13698 0 0 0 136 7 0 0 20 0 1 0 120392695 50036736 10300 18446744073709551615 4194304 5690517 140734346198064 140734346195704 4804448 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/20264/statm: 12216 10300 159 366 0 11847 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 58076

[startup+3.10027 s]
/proc/loadavg: 0.87 0.97 0.99 2/66 20264
/proc/meminfo: memFree=219500/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=2.93
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 761 27440 0 0 0 0 277 16 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 9212

[startup+6.30032 s]
/proc/loadavg: 0.87 0.97 0.99 2/66 20265
/proc/meminfo: memFree=125508/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=2.93
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 761 27440 0 0 0 0 277 16 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251742320 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20265] ppid=20248 vsize=225088 CPUtime=3.29
/proc/20265/stat : 20265 (gringo) R 20248 20248 1745 0 -1 4202496 53612 0 0 0 306 23 0 0 20 0 1 0 120392987 230490112 48976 18446744073709551615 4194304 6531320 140736024253456 140736024249384 4452664 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20265/statm: 56272 48976 283 571 0 55693 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 234300

[startup+12.7004 s]
/proc/loadavg: 0.89 0.97 0.99 2/67 20267
/proc/meminfo: memFree=175224/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=85936 CPUtime=5.11
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 25176 0 0 0 501 10 0 0 20 0 1 0 120393442 87998464 21168 18446744073709551615 4194304 6238623 140734672409072 140734672406096 4332782 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 21484 21168 263 500 0 20981 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 117188

[startup+25.5004 s]
/proc/loadavg: 0.91 0.97 0.99 2/67 20267
/proc/meminfo: memFree=174852/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=85936 CPUtime=17.78
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 25215 0 0 0 1768 10 0 0 20 0 1 0 120393442 87998464 21207 18446744073709551615 4194304 6238623 140734672409072 140734672406096 4684992 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 21484 21207 263 500 0 20981 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.2
Current children cumulated vsize (KiB) 117188

[startup+51.1004 s]
/proc/loadavg: 0.94 0.97 0.99 2/67 20267
/proc/meminfo: memFree=174728/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=85936 CPUtime=43.12
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 25215 0 0 0 4302 10 0 0 20 0 1 0 120393442 87998464 21207 18446744073709551615 4194304 6238623 140734672409072 140734672406096 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 21484 21207 263 500 0 20981 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.54
Current children cumulated vsize (KiB) 117188

[startup+102.3 s]
/proc/loadavg: 1.05 1.00 1.00 2/67 20275
/proc/meminfo: memFree=138892/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=121860 CPUtime=93.78
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 34152 0 0 0 9362 16 0 0 20 0 1 0 120393442 124784640 30144 18446744073709551615 4194304 6238623 140734672409072 140734672405624 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 30465 30144 263 500 0 29962 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.2
Current children cumulated vsize (KiB) 153112

[startup+162.3 s]
/proc/loadavg: 1.02 1.00 1.00 2/67 20275
/proc/meminfo: memFree=59036/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=204848 CPUtime=153.17
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 54708 0 0 0 15287 30 0 0 20 0 1 0 120393442 209764352 50700 18446744073709551615 4194304 6238623 140734672409072 140734672405624 4330304 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 51212 50700 263 500 0 50709 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 160.59
Current children cumulated vsize (KiB) 236100

[startup+222.309 s]
/proc/loadavg: 1.10 1.03 1.01 2/67 20275
/proc/meminfo: memFree=49860/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=211588 CPUtime=212.6
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 56382 0 0 0 21228 32 0 0 20 0 1 0 120393442 216666112 52374 18446744073709551615 4194304 6238623 140734672409072 140734672405624 4331892 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 52897 52374 263 500 0 52394 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 220.02
Current children cumulated vsize (KiB) 242840

[startup+282.3 s]
/proc/loadavg: 1.04 1.02 1.00 2/67 20275
/proc/meminfo: memFree=20720/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=241772 CPUtime=272.02
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 63704 0 0 0 27167 35 0 0 20 0 1 0 120393442 247574528 59696 18446744073709551615 4194304 6238623 140734672409072 140734672406096 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 60443 59696 263 500 0 59940 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 279.44
Current children cumulated vsize (KiB) 273024



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.1 s]
/proc/loadavg: 1.02 1.02 1.00 2/67 20275
/proc/meminfo: memFree=9560/1022884 swapFree=0/0
[pid=20248] ppid=20247 vsize=9212 CPUtime=7.4
/proc/20248/stat : 20248 (aspcud-full) S 20247 20248 1745 0 -1 4202496 801 99272 0 0 0 0 686 54 20 0 1 0 120392691 9433088 365 18446744073709551615 4194304 5129932 140733251743664 140733251741728 140268750509150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20248/statm: 2303 365 303 229 0 63 0
[pid=20266] ppid=20248 vsize=252672 CPUtime=292.67
/proc/20266/stat : 20266 (clasp) R 20248 20248 1745 0 -1 4202496 66425 0 0 0 29231 36 0 0 20 0 1 0 120393442 258736128 62417 18446744073709551615 4194304 6238623 140734672409072 140734672406096 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20266/statm: 63168 62417 263 500 0 62665 0
[pid=20267] ppid=20248 vsize=22040 CPUtime=0.02
/proc/20267/stat : 20267 (parse.py) S 20248 20248 1745 0 -1 4202496 1310 0 9 0 2 0 0 0 20 0 1 0 120393442 22568960 1129 18446744073709551615 4194304 6642060 140737025212576 140737025210936 140464386258720 0 0 16777220 20994 0 0 0 17 0 0 0 7 0 0
/proc/20267/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 283924

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.14
CPU time (s): 300.147
CPU user time (s): 299.211
CPU system time (s): 0.936058
CPU usage (%): 99.0127
Max. virtual memory (cumulated for all children) (KiB): 314772

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.211
system time used= 0.936058
maximum resident set size= 252380
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 168117
page faults= 9
swaps= 0
block input operations= 43408
block output operations= 30592
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 81
involuntary context switches= 34115

runsolver used 0.65204 second user time and 1.6361 second system time

The end