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/trendy-size/upgrade/difficult/rand313.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand313.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand313.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-unsat_recommends(solution),-count(new) 

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.94 0.96 2/59 17146
/proc/meminfo: memFree=699744/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=3152 CPUtime=0
/proc/17146/stat : 17146 (runsolver) R 17145 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119569286 3227648 32 18446744073709551615 134512640 134586868 4289308432 4289306480 4151690288 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17146/statm: 864 40 30 229 0 32 0

[startup+0.204019 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 17146
/proc/meminfo: memFree=699744/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=0.03
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 739 3618 1 0 0 0 2 1 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300272 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 17146
/proc/meminfo: memFree=699744/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=0.03
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 739 3618 1 0 0 0 2 1 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.400273 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 17146
/proc/meminfo: memFree=699744/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=0.03
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 739 3618 1 0 0 0 2 1 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700192 s]
/proc/loadavg: 0.87 0.94 0.96 2/59 17146
/proc/meminfo: memFree=699744/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=0.03
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 739 3618 1 0 0 0 2 1 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.87 0.94 0.96 2/61 17162
/proc/meminfo: memFree=638960/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=0.03
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 739 3618 1 0 0 0 2 1 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17162] ppid=17146 vsize=50676 CPUtime=1.43
/proc/17162/stat : 17162 (cudf2lp) R 17146 17146 1750 0 -1 4202496 15122 0 0 0 136 7 0 0 20 0 1 0 119569290 51892224 11723 18446744073709551615 4194304 5690517 140733911014560 140733911012200 4360961 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/17162/statm: 12669 11723 160 366 0 12300 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 59888

[startup+3.10032 s]
/proc/loadavg: 0.87 0.94 0.96 2/61 17162
/proc/meminfo: memFree=590724/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=0.03
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 739 3618 1 0 0 0 2 1 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17162] ppid=17146 vsize=125284 CPUtime=3.02
/proc/17162/stat : 17162 (cudf2lp) R 17146 17146 1750 0 -1 4202496 35292 0 0 0 284 18 0 0 20 0 1 0 119569290 128290816 28564 18446744073709551615 4194304 5690517 140733911014560 140733911011688 4253177 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/17162/statm: 31321 28564 168 366 0 30952 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 134496

[startup+6.30031 s]
/proc/loadavg: 0.88 0.94 0.96 2/61 17163
/proc/meminfo: memFree=596676/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=4.26
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 763 42941 1 0 0 0 398 28 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17163] ppid=17146 vsize=107628 CPUtime=1.96
/proc/17163/stat : 17163 (gringo) R 17146 17146 1750 0 -1 4202496 27435 0 0 0 186 10 0 0 20 0 1 0 119569718 110211072 23249 18446744073709551615 4194304 6531320 140734071583680 140734071580296 4359075 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17163/statm: 26907 23249 276 571 0 26328 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 116840

[startup+12.7003 s]
/proc/loadavg: 0.89 0.94 0.96 2/61 17163
/proc/meminfo: memFree=184748/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=4.26
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 763 42941 1 0 0 0 398 28 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013543152 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17163] ppid=17146 vsize=587756 CPUtime=8.3
/proc/17163/stat : 17163 (gringo) R 17146 17146 1750 0 -1 4202496 137341 0 0 0 777 53 0 0 20 0 1 0 119569718 601862144 120865 18446744073709551615 4194304 6531320 140734071583680 140734071580296 5511058 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17163/statm: 146939 120865 282 571 0 146360 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 596968

[startup+25.5033 s]
/proc/loadavg: 0.91 0.94 0.96 2/62 17165
/proc/meminfo: memFree=426300/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=233796 CPUtime=8.86
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 71059 0 0 0 857 29 0 0 20 0 1 0 119570940 239407104 57948 18446744073709551615 4194304 6238623 140734504097760 140734504094784 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 58449 57948 263 500 0 57946 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 265048

[startup+51.1003 s]
/proc/loadavg: 0.94 0.95 0.96 2/62 17165
/proc/meminfo: memFree=426300/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=233796 CPUtime=34.26
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 71060 0 0 0 3397 29 0 0 20 0 1 0 119570940 239407104 57949 18446744073709551615 4194304 6238623 140734504097760 140734504094784 4332534 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 58449 57949 264 500 0 57946 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.56
Current children cumulated vsize (KiB) 265048

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.96 2/62 17165
/proc/meminfo: memFree=314700/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=345028 CPUtime=85.07
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 98973 0 0 0 8462 45 0 0 20 0 1 0 119570940 353308672 85862 18446744073709551615 4194304 6238623 140734504097760 140734504094312 4677225 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 86257 85862 264 500 0 85754 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.37
Current children cumulated vsize (KiB) 376280

[startup+162.3 s]
/proc/loadavg: 0.99 0.96 0.96 2/62 17165
/proc/meminfo: memFree=309988/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=349568 CPUtime=144.62
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 100119 0 0 0 14416 46 0 0 20 0 1 0 119570940 357957632 87008 18446744073709551615 4194304 6238623 140734504097760 140734504094312 4635134 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 87392 87008 264 500 0 86889 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.92
Current children cumulated vsize (KiB) 380820

[startup+222.3 s]
/proc/loadavg: 0.99 0.96 0.96 2/62 17165
/proc/meminfo: memFree=285808/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=373884 CPUtime=204.18
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 106191 0 0 0 20370 48 0 0 20 0 1 0 119570940 382857216 93080 18446744073709551615 4194304 6238623 140734504097760 140734504094312 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 93471 93080 264 500 0 92968 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.48
Current children cumulated vsize (KiB) 405136

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.96 2/62 17165
/proc/meminfo: memFree=243524/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=416000 CPUtime=263.73
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 116728 0 0 0 26319 54 0 0 20 0 1 0 119570940 425984000 103617 18446744073709551615 4194304 6238623 140734504097760 140734504094312 4321271 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 104000 103617 264 500 0 103497 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 280.03
Current children cumulated vsize (KiB) 447252



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.5 s]
/proc/loadavg: 0.99 0.97 0.96 2/62 17165
/proc/meminfo: memFree=243524/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=416000 CPUtime=283.78
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 116728 0 0 0 28324 54 0 0 20 0 1 0 119570940 425984000 103617 18446744073709551615 4194304 6238623 140734504097760 140734504094312 4321269 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 104000 103617 264 500 0 103497 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.08
Current children cumulated vsize (KiB) 447252

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+302.5 s]
/proc/loadavg: 0.99 0.97 0.96 2/62 17165
/proc/meminfo: memFree=243524/1022884 swapFree=0/0
[pid=17146] ppid=17145 vsize=9212 CPUtime=16.28
/proc/17146/stat : 17146 (aspcud-full) S 17145 17146 1750 0 -1 4202496 801 221849 1 0 0 0 1506 122 20 0 1 0 119569286 9433088 364 18446744073709551615 4194304 5129932 140737013544496 140737013542560 140265678902366 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17146/statm: 2303 364 303 229 0 63 0
[pid=17164] ppid=17146 vsize=416000 CPUtime=283.78
/proc/17164/stat : 17164 (clasp) R 17146 17146 1750 0 -1 4202496 116728 0 0 0 28324 54 0 0 20 0 1 0 119570940 425984000 103617 18446744073709551615 4194304 6238623 140734504097760 140734504094312 4321269 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17164/statm: 104000 103617 264 500 0 103497 0
[pid=17165] ppid=17146 vsize=22040 CPUtime=0.02
/proc/17165/stat : 17165 (parse.py) S 17146 17146 1750 0 -1 4202496 1319 0 0 0 0 2 0 0 20 0 1 0 119570940 22568960 1128 18446744073709551615 4194304 6642060 140734127250208 140734127248568 140150951741216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17165/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.08
Current children cumulated vsize (KiB) 447252

Child status: 0
Real time (s): 302.558
CPU time (s): 300.163
CPU user time (s): 298.331
CPU system time (s): 1.83211
CPU usage (%): 99.2084
Max. virtual memory (cumulated for all children) (KiB): 783996

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.331
system time used= 1.83211
maximum resident set size= 649712
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 341026
page faults= 1
swaps= 0
block input operations= 68552
block output operations= 81952
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 81
involuntary context switches= 34414

runsolver used 0.548034 second user time and 1.10007 second system time

The end