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/rand242.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand242.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand242.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: 1.01 1.08 1.07 2/64 15233
/proc/meminfo: memFree=778092/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=3152 CPUtime=0
/proc/15233/stat : 15233 (runsolver) D 15232 15233 1745 0 -1 4202560 75 0 0 0 0 0 0 0 20 0 1 0 118784143 3227648 97 18446744073709551615 134512640 134586868 4286965968 4286964016 4151817264 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/15233/statm: 788 97 64 19 0 73 0

[startup+0.139399 s]
/proc/loadavg: 1.01 1.08 1.07 2/64 15233
/proc/meminfo: memFree=778092/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=0.04
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 678 3085 2 4 0 0 2 2 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200326 s]
/proc/loadavg: 1.01 1.08 1.07 2/64 15233
/proc/meminfo: memFree=778092/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=0.05
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 732 3619 2 6 0 0 3 2 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300307 s]
/proc/loadavg: 1.01 1.08 1.07 2/64 15233
/proc/meminfo: memFree=778092/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=0.05
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 732 3619 2 6 0 0 3 2 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700224 s]
/proc/loadavg: 1.01 1.08 1.07 2/64 15233
/proc/meminfo: memFree=778092/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=0.05
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 732 3619 2 6 0 0 3 2 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.01 1.08 1.07 2/66 15249
/proc/meminfo: memFree=743968/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=0.05
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 732 3619 2 6 0 0 3 2 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15249] ppid=15233 vsize=30012 CPUtime=1.26
/proc/15249/stat : 15249 (cudf2lp) R 15233 15233 1745 0 -1 4202496 8848 0 16 0 122 4 0 0 20 0 1 0 118784158 30732288 7131 18446744073709551615 4194304 5690517 140734940769072 140734940766712 4361584 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/15249/statm: 7503 7131 159 366 0 7134 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 39224

[startup+3.10031 s]
/proc/loadavg: 1.01 1.08 1.07 2/66 15249
/proc/meminfo: memFree=712348/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=0.05
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 732 3619 2 6 0 0 3 2 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15249] ppid=15233 vsize=106344 CPUtime=2.83
/proc/15249/stat : 15249 (cudf2lp) R 15233 15233 1745 0 -1 4202496 26376 0 16 0 274 9 0 0 20 0 1 0 118784158 108896256 22994 18446744073709551615 4194304 5690517 140734940769072 140734940765272 4376724 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/15249/statm: 26586 22994 160 366 0 26217 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 115556

[startup+6.30031 s]
/proc/loadavg: 1.01 1.08 1.07 1/66 15250
/proc/meminfo: memFree=725492/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=5.19
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 758 42924 2 22 0 0 489 30 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15250] ppid=15233 vsize=25140 CPUtime=0.77
/proc/15250/stat : 15250 (gringo) R 15233 15233 1745 0 -1 4202496 6422 0 22 0 74 3 0 0 20 0 1 0 118784687 25743360 5333 18446744073709551615 4194304 6531320 140734486298928 140734486295544 5119440 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/15250/statm: 6285 5333 259 571 0 5706 0
Current children cumulated CPU time (s) 5.96
Current children cumulated vsize (KiB) 34352

[startup+12.7003 s]
/proc/loadavg: 1.01 1.08 1.07 2/66 15250
/proc/meminfo: memFree=437440/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=5.19
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 758 42924 2 22 0 0 489 30 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579824 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15250] ppid=15233 vsize=420060 CPUtime=7.12
/proc/15250/stat : 15250 (gringo) R 15233 15233 1745 0 -1 4202496 99274 0 23 0 658 54 0 0 20 0 1 0 118784687 430141440 82822 18446744073709551615 4194304 6531320 140734486298928 140734486295352 5520984 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/15250/statm: 105015 82822 282 571 0 104436 0
Current children cumulated CPU time (s) 12.31
Current children cumulated vsize (KiB) 429272

[startup+25.5004 s]
/proc/loadavg: 1.01 1.08 1.07 2/67 15252
/proc/meminfo: memFree=460868/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=238240 CPUtime=6.7
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 71425 0 22 0 644 26 0 0 20 0 1 0 118786006 243957760 58314 18446744073709551615 4194304 6238623 140734647213728 140734647210752 4372090 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 59560 58314 263 500 0 59057 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.9
Current children cumulated vsize (KiB) 269492

[startup+51.1004 s]
/proc/loadavg: 1.00 1.07 1.07 2/67 15252
/proc/meminfo: memFree=457644/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=238240 CPUtime=32.03
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 72325 0 22 0 3177 26 0 0 20 0 1 0 118786006 243957760 59214 18446744073709551615 4194304 6238623 140734647213728 140734647210752 4322637 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 59560 59214 264 500 0 59057 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.23
Current children cumulated vsize (KiB) 269492

[startup+102.3 s]
/proc/loadavg: 1.00 1.06 1.06 2/67 15252
/proc/meminfo: memFree=378656/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=317064 CPUtime=82.82
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 92001 0 22 0 8247 35 0 0 20 0 1 0 118786006 324673536 78890 18446744073709551615 4194304 6238623 140734647213728 140734647210280 4687697 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 79266 78890 264 500 0 78763 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.02
Current children cumulated vsize (KiB) 348316

[startup+162.3 s]
/proc/loadavg: 1.00 1.04 1.06 2/67 15252
/proc/meminfo: memFree=364272/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=331272 CPUtime=142.35
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 95560 0 22 0 14199 36 0 0 20 0 1 0 118786006 339222528 82449 18446744073709551615 4194304 6238623 140734647213728 140734647210280 4688016 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 82818 82449 264 500 0 82315 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.55
Current children cumulated vsize (KiB) 362524

[startup+222.304 s]
/proc/loadavg: 1.00 1.03 1.05 2/67 15252
/proc/meminfo: memFree=345052/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=351216 CPUtime=201.89
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 100345 0 22 0 20152 37 0 0 20 0 1 0 118786006 359645184 87234 18446744073709551615 4194304 6238623 140734647213728 140734647210280 4332615 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 87804 87234 264 500 0 87301 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.09
Current children cumulated vsize (KiB) 382468

[startup+282.3 s]
/proc/loadavg: 1.04 1.04 1.05 2/67 15252
/proc/meminfo: memFree=335752/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=360428 CPUtime=261.43
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 102663 0 22 0 26105 38 0 0 20 0 1 0 118786006 369078272 89552 18446744073709551615 4194304 6238623 140734647213728 140734647210280 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 90107 89552 264 500 0 89604 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.63
Current children cumulated vsize (KiB) 391680



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.9 s]
/proc/loadavg: 1.09 1.05 1.06 2/67 15252
/proc/meminfo: memFree=335504/1022884 swapFree=0/0
[pid=15233] ppid=15232 vsize=9212 CPUtime=18.18
/proc/15233/stat : 15233 (aspcud-full) S 15232 15233 1745 0 -1 4202496 798 223345 2 45 0 0 1682 136 20 0 1 0 118784143 9433088 364 18446744073709551615 4194304 5129932 140736611581168 140736611579232 140058842346590 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15233/statm: 2303 364 303 229 0 63 0
[pid=15251] ppid=15233 vsize=360696 CPUtime=281.86
/proc/15251/stat : 15251 (clasp) R 15233 15233 1745 0 -1 4202496 102736 0 22 0 28148 38 0 0 20 0 1 0 118786006 369352704 89625 18446744073709551615 4194304 6238623 140734647213728 140734647210280 4685008 0 0 16781316 18946 0 0 0 17 0 0 0 8 0 0
/proc/15251/statm: 90174 89625 264 500 0 89671 0
[pid=15252] ppid=15233 vsize=22040 CPUtime=0.02
/proc/15252/stat : 15252 (parse.py) S 15233 15233 1745 0 -1 4202496 1317 0 1 0 1 1 0 0 20 0 1 0 118786006 22568960 1128 18446744073709551615 4194304 6642060 140734120031536 140734120029896 140415955781408 0 0 16777220 20994 0 0 0 17 0 0 0 2 0 0
/proc/15252/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 391948

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.006
CPU time (s): 300.191
CPU user time (s): 298.391
CPU system time (s): 1.80011
CPU usage (%): 99.0708
Max. virtual memory (cumulated for all children) (KiB): 796780

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.391
system time used= 1.80011
maximum resident set size= 655860
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 328511
page faults= 72
swaps= 0
block input operations= 80048
block output operations= 82272
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 175
involuntary context switches= 34458

runsolver used 0.544034 second user time and 1.27208 second system time

The end