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/install/rand308.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand308.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand308.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.94 1.01 1.04 2/64 15259
/proc/meminfo: memFree=736552/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9204 CPUtime=0
/proc/15259/stat : 15259 (aspcud-full) R 15258 15259 1745 0 -1 4202496 421 0 0 0 0 0 0 0 20 0 1 0 118816484 9424896 329 18446744073709551615 4194304 5129932 140737279337104 140737279334072 139728088188442 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2301 329 271 229 0 61 0

[startup+0.206982 s]
/proc/loadavg: 0.94 1.01 1.04 2/64 15259
/proc/meminfo: memFree=736552/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=0.05
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 740 3617 0 0 0 0 4 1 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300326 s]
/proc/loadavg: 0.94 1.01 1.04 2/64 15259
/proc/meminfo: memFree=736552/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=0.05
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 740 3617 0 0 0 0 4 1 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.400315 s]
/proc/loadavg: 0.94 1.01 1.04 2/64 15259
/proc/meminfo: memFree=736552/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=0.05
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 740 3617 0 0 0 0 4 1 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 0.94 1.01 1.04 2/64 15259
/proc/meminfo: memFree=736552/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=0.05
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 740 3617 0 0 0 0 4 1 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.94 1.01 1.04 2/66 15275
/proc/meminfo: memFree=699824/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=0.05
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 740 3617 0 0 0 0 4 1 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15275] ppid=15259 vsize=56544 CPUtime=1.43
/proc/15275/stat : 15275 (cudf2lp) R 15259 15259 1745 0 -1 4202496 13808 0 0 0 139 4 0 0 20 0 1 0 118816488 57901056 12075 18446744073709551615 4194304 5690517 140733808867920 140733808864088 4370869 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/15275/statm: 14136 12075 160 366 0 13767 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 65756

[startup+3.10033 s]
/proc/loadavg: 0.94 1.01 1.04 2/66 15275
/proc/meminfo: memFree=668204/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=0.05
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 740 3617 0 0 0 0 4 1 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15275] ppid=15259 vsize=93028 CPUtime=3.02
/proc/15275/stat : 15275 (cudf2lp) R 15259 15259 1745 0 -1 4202496 26551 0 0 0 290 12 0 0 20 0 1 0 118816488 95260672 19824 18446744073709551615 4194304 5690517 140733808867920 140733808865560 4956107 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/15275/statm: 23257 19824 160 366 0 22888 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.94 1.01 1.04 2/66 15276
/proc/meminfo: memFree=678124/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=5.25
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 767 42938 0 0 0 0 496 29 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15276] ppid=15259 vsize=28856 CPUtime=0.97
/proc/15276/stat : 15276 (gringo) R 15259 15259 1745 0 -1 4202496 7578 0 0 0 94 3 0 0 20 0 1 0 118817015 29548544 6467 18446744073709551615 4194304 6531320 140734387368880 140734387365496 5520721 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15276/statm: 7214 6467 259 571 0 6635 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 38068

[startup+12.7003 s]
/proc/loadavg: 0.95 1.01 1.04 2/66 15276
/proc/meminfo: memFree=383376/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=5.25
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 767 42938 0 0 0 0 496 29 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335760 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15276] ppid=15259 vsize=428300 CPUtime=7.3
/proc/15276/stat : 15276 (gringo) R 15259 15259 1745 0 -1 4202496 101756 0 0 0 686 44 0 0 20 0 1 0 118817015 438579200 85281 18446744073709551615 4194304 6531320 140734387368880 140734387365496 4358969 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15276/statm: 107075 85281 282 571 0 106496 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 437512

[startup+25.5112 s]
/proc/loadavg: 0.96 1.01 1.04 2/67 15278
/proc/meminfo: memFree=426456/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=233944 CPUtime=6.84
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 71095 0 0 0 655 29 0 0 20 0 1 0 118818340 239558656 57981 18446744073709551615 4194304 6238623 140734504280864 140734504277888 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 58486 57981 263 500 0 57983 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.08
Current children cumulated vsize (KiB) 265196

[startup+51.1004 s]
/proc/loadavg: 0.97 1.01 1.04 2/67 15278
/proc/meminfo: memFree=426332/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=233944 CPUtime=32.19
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 71167 0 0 0 3189 30 0 0 20 0 1 0 118818340 239558656 58053 18446744073709551615 4194304 6238623 140734504280864 140734504277888 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 58486 58053 264 500 0 57983 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.43
Current children cumulated vsize (KiB) 265196

[startup+102.3 s]
/proc/loadavg: 0.99 1.00 1.03 2/67 15278
/proc/meminfo: memFree=426208/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=233944 CPUtime=82.87
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 71170 0 0 0 8257 30 0 0 20 0 1 0 118818340 239558656 58056 18446744073709551615 4194304 6238623 140734504280864 140734504277888 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 58486 58056 264 500 0 57983 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.11
Current children cumulated vsize (KiB) 265196

[startup+162.3 s]
/proc/loadavg: 0.99 1.00 1.03 2/67 15278
/proc/meminfo: memFree=399176/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=260520 CPUtime=142.4
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 77916 0 0 0 14208 32 0 0 20 0 1 0 118818340 266772480 64802 18446744073709551615 4194304 6238623 140734504280864 140734504277416 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 65130 64802 264 500 0 64627 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.64
Current children cumulated vsize (KiB) 291772

[startup+222.3 s]
/proc/loadavg: 1.15 1.03 1.03 2/67 15278
/proc/meminfo: memFree=332836/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=327136 CPUtime=201.94
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 94510 0 0 0 20154 40 0 0 20 0 1 0 118818340 334987264 81396 18446744073709551615 4194304 6238623 140734504280864 140734504277416 4676741 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 81784 81396 264 500 0 81281 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.18
Current children cumulated vsize (KiB) 358388

[startup+282.3 s]
/proc/loadavg: 1.06 1.03 1.03 2/67 15278
/proc/meminfo: memFree=316840/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=343308 CPUtime=261.48
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 98516 0 0 0 26104 44 0 0 20 0 1 0 118818340 351547392 85402 18446744073709551615 4194304 6238623 140734504280864 140734504277416 4409931 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 85827 85402 264 500 0 85324 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.72
Current children cumulated vsize (KiB) 374560



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.8 s]
/proc/loadavg: 1.11 1.04 1.03 2/67 15278
/proc/meminfo: memFree=308532/1022884 swapFree=0/0
[pid=15259] ppid=15258 vsize=9212 CPUtime=18.22
/proc/15259/stat : 15259 (aspcud-full) S 15258 15259 1745 0 -1 4202496 808 222038 0 0 0 0 1691 131 20 0 1 0 118816484 9433088 364 18446744073709551615 4194304 5129932 140737279337104 140737279335168 139728088024158 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15259/statm: 2303 364 303 229 0 63 0
[pid=15277] ppid=15259 vsize=351704 CPUtime=281.83
/proc/15277/stat : 15277 (clasp) R 15259 15259 1745 0 -1 4202496 100589 0 0 0 28138 45 0 0 20 0 1 0 118818340 360144896 87475 18446744073709551615 4194304 6238623 140734504280864 140734504277416 4635196 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/15277/statm: 87926 87475 264 500 0 87423 0
[pid=15278] ppid=15259 vsize=22040 CPUtime=0.02
/proc/15278/stat : 15278 (parse.py) S 15259 15259 1745 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118818340 22568960 1128 18446744073709551615 4194304 6642060 140735399927184 140735399925544 140004464502560 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15278/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 382956

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): 302.858
CPU time (s): 300.155
CPU user time (s): 298.327
CPU system time (s): 1.82811
CPU usage (%): 99.1074
Max. virtual memory (cumulated for all children) (KiB): 784472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.327
system time used= 1.82811
maximum resident set size= 650484
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 325078
page faults= 0
swaps= 0
block input operations= 68440
block output operations= 82032
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 81
involuntary context switches= 34318

runsolver used 0.580036 second user time and 1.29608 second system time

The end