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/aspuncud-full-1.7/trendy-size/upgrade/difficult/rand491.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand491.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/upgrade/difficult/rand491.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.19 1.07 1.00 2/59 18117
/proc/meminfo: memFree=659112/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=1068 CPUtime=0
/proc/18117/stat : 18117 (aspuncud-full) D 18116 18117 1750 0 -1 4194304 76 0 0 0 0 0 0 0 20 0 1 0 119715696 1093632 1 18446744073709551615 0 0 140734642125725 4287112736 4151235632 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/18117/statm: 267 1 0 0 0 28 0

[startup+0.160169 s]
/proc/loadavg: 1.19 1.07 1.00 2/59 18117
/proc/meminfo: memFree=659112/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=0.03
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 692 2799 2 7 0 0 2 1 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200299 s]
/proc/loadavg: 1.19 1.07 1.00 2/59 18117
/proc/meminfo: memFree=659112/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=0.03
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 692 2799 2 7 0 0 2 1 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300257 s]
/proc/loadavg: 1.19 1.07 1.00 2/59 18117
/proc/meminfo: memFree=659112/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=0.03
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 692 2799 2 7 0 0 2 1 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70021 s]
/proc/loadavg: 1.19 1.07 1.00 2/59 18117
/proc/meminfo: memFree=659112/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=0.03
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 692 2799 2 7 0 0 2 1 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 1.17 1.07 1.00 2/61 18130
/proc/meminfo: memFree=613960/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=0.03
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 692 2799 2 7 0 0 2 1 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18130] ppid=18117 vsize=50676 CPUtime=1.33
/proc/18130/stat : 18130 (cudf2lp) R 18117 18117 1750 0 -1 4202496 14746 0 1 0 126 7 0 0 20 0 1 0 119715708 51892224 11348 18446744073709551615 4194304 5690517 140733816284960 140733816282600 4365872 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/18130/statm: 12669 11348 160 366 0 12300 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 59888

[startup+3.10028 s]
/proc/loadavg: 1.17 1.07 1.00 2/61 18130
/proc/meminfo: memFree=552456/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=0.03
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 692 2799 2 7 0 0 2 1 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18130] ppid=18117 vsize=141388 CPUtime=2.88
/proc/18130/stat : 18130 (cudf2lp) R 18117 18117 1750 0 -1 4202496 39313 0 1 0 274 14 0 0 20 0 1 0 119715708 144781312 32586 18446744073709551615 4194304 5690517 140733816284960 140733816282088 4970346 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/18130/statm: 35347 32586 169 366 0 34978 0
Current children cumulated CPU time (s) 2.91
Current children cumulated vsize (KiB) 150600

[startup+6.30027 s]
/proc/loadavg: 1.16 1.07 1.00 2/61 18131
/proc/meminfo: memFree=546504/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=3.65
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 719 42121 2 8 0 0 345 20 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18131] ppid=18117 vsize=159580 CPUtime=2.39
/proc/18131/stat : 18131 (gringo) R 18117 18117 1750 0 -1 4202496 40670 0 1 0 223 16 0 0 20 0 1 0 119716080 163409920 32389 18446744073709551615 4194304 6531320 140736627563984 140736627560600 5510962 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/18131/statm: 39895 32389 277 571 0 39316 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 168792

[startup+12.7003 s]
/proc/loadavg: 1.23 1.09 1.01 2/61 18131
/proc/meminfo: memFree=9588/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=3.65
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 719 42121 2 8 0 0 345 20 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642121344 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18131] ppid=18117 vsize=719832 CPUtime=8.58
/proc/18131/stat : 18131 (gringo) R 18117 18117 1750 0 -1 4202496 180438 0 1 0 800 58 0 0 20 0 1 0 119716080 737107968 150599 18446744073709551615 4194304 6531320 140736627563984 140736627561672 4318262 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/18131/statm: 179958 150599 283 571 0 179379 0
Current children cumulated CPU time (s) 12.23
Current children cumulated vsize (KiB) 729044

[startup+25.5003 s]
/proc/loadavg: 1.17 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=12.31
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69602 0 2 0 1212 19 0 0 20 0 1 0 119717002 235335680 56985 18446744073709551615 4194304 6012874 140735944995376 140735944994696 4506567 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 56985 230 444 0 57003 0
[pid=18133] ppid=18117 vsize=22324 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1383 0 0 0 0 0 0 0 20 0 1 0 119717002 22859776 1192 18446744073709551615 4194304 6642060 140733783310064 140733783307912 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5581 1192 508 598 0 667 0
Current children cumulated CPU time (s) 24.92
Current children cumulated vsize (KiB) 261356

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

[startup+25.6004 s]
/proc/loadavg: 1.17 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=12.41
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69602 0 2 0 1222 19 0 0 20 0 1 0 119717002 235335680 56985 18446744073709551615 4194304 6012874 140735944995376 140735944994696 4555188 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 56985 230 444 0 57003 0
[pid=18133] ppid=18117 vsize=22324 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1383 0 0 0 0 0 0 0 20 0 1 0 119717002 22859776 1192 18446744073709551615 4194304 6642060 140733783310064 140733783307912 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5581 1192 508 598 0 667 0
Current children cumulated CPU time (s) 25.02
Current children cumulated vsize (KiB) 261356

[startup+32.0033 s]
/proc/loadavg: 1.16 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=18.76
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69602 0 2 0 1856 20 0 0 20 0 1 0 119717002 235335680 56985 18446744073709551615 4194304 6012874 140735944995376 140735944994664 4278496 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 56985 230 444 0 57003 0
[pid=18133] ppid=18117 vsize=22324 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1383 0 0 0 0 0 0 0 20 0 1 0 119717002 22859776 1192 18446744073709551615 4194304 6642060 140733783310064 140733783307912 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5581 1192 508 598 0 667 0
Current children cumulated CPU time (s) 31.37
Current children cumulated vsize (KiB) 261356

[startup+35.2003 s]
/proc/loadavg: 1.15 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=21.93
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69602 0 2 0 2173 20 0 0 20 0 1 0 119717002 235335680 56985 18446744073709551615 4194304 6012874 140735944995376 140735944994696 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 56985 230 444 0 57003 0
[pid=18133] ppid=18117 vsize=22324 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1383 0 0 0 0 0 0 0 20 0 1 0 119717002 22859776 1192 18446744073709551615 4194304 6642060 140733783310064 140733783307912 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5581 1192 508 598 0 667 0
Current children cumulated CPU time (s) 34.54
Current children cumulated vsize (KiB) 261356

[startup+36.0003 s]
/proc/loadavg: 1.15 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=22.72
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69602 0 2 0 2252 20 0 0 20 0 1 0 119717002 235335680 56985 18446744073709551615 4194304 6012874 140735944995376 140735944994696 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 56985 230 444 0 57003 0
[pid=18133] ppid=18117 vsize=22324 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1383 0 0 0 0 0 0 0 20 0 1 0 119717002 22859776 1192 18446744073709551615 4194304 6642060 140733783310064 140733783307912 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5581 1192 508 598 0 667 0
Current children cumulated CPU time (s) 35.33
Current children cumulated vsize (KiB) 261356

[startup+36.8003 s]
/proc/loadavg: 1.15 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=23.51
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69602 0 2 0 2331 20 0 0 20 0 1 0 119717002 235335680 56985 18446744073709551615 4194304 6012874 140735944995376 140735944994696 4548105 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 56985 230 444 0 57003 0
[pid=18133] ppid=18117 vsize=22324 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1383 0 0 0 0 0 0 0 20 0 1 0 119717002 22859776 1192 18446744073709551615 4194304 6642060 140733783310064 140733783307912 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5581 1192 508 598 0 667 0
Current children cumulated CPU time (s) 36.12
Current children cumulated vsize (KiB) 261356

[startup+37.201 s]
/proc/loadavg: 1.15 1.08 1.00 2/62 18133
/proc/meminfo: memFree=435740/1022884 swapFree=0/0
[pid=18117] ppid=18116 vsize=9212 CPUtime=12.61
/proc/18117/stat : 18117 (aspuncud-full) S 18116 18117 1750 0 -1 4202496 758 222563 2 9 0 0 1166 95 20 0 1 0 119715696 9433088 364 18446744073709551615 4194304 5129932 140734642122688 140734642120752 140144764351582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/18117/statm: 2303 364 303 229 0 63 0
[pid=18132] ppid=18117 vsize=229820 CPUtime=23.91
/proc/18132/stat : 18132 (unclasp) R 18117 18117 1750 0 -1 4202496 69609 0 2 0 2369 22 0 0 20 0 1 0 119717002 235335680 38560 18446744073709551615 4194304 6012874 140735944995376 140735944994776 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/18132/statm: 57455 38560 237 444 0 57003 0
[pid=18133] ppid=18117 vsize=22460 CPUtime=0
/proc/18133/stat : 18133 (parse.py) S 18117 18117 1750 0 -1 4202496 1416 0 0 0 0 0 0 0 20 0 1 0 119717002 22999040 1225 18446744073709551615 4194304 6642060 140733783310064 140733783308264 140729075238688 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/18133/statm: 5615 1225 508 598 0 701 0
Current children cumulated CPU time (s) 36.52
Current children cumulated vsize (KiB) 261492

Child status: 0
Real time (s): 37.2576
CPU time (s): 36.6183
CPU user time (s): 35.3782
CPU system time (s): 1.24008
CPU usage (%): 98.2842
Max. virtual memory (cumulated for all children) (KiB): 798684

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 35.3782
system time used= 1.24008
maximum resident set size= 655856
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 294630
page faults= 13
swaps= 0
block input operations= 69544
block output operations= 82296
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 187
involuntary context switches= 4363

runsolver used 0.060003 second user time and 0.144009 second system time

The end