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/install/rand984.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand984.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/install/rand984.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.02 0.96 2/56 23810
/proc/meminfo: memFree=700804/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9204 CPUtime=0
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 41424888 9424896 332 18446744073709551615 4194304 5129932 140734192299584 140734192297048 139674005477152 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2301 332 272 229 0 61 0

[startup+0.12258 s]
/proc/loadavg: 1.01 1.02 0.96 2/56 23810
/proc/meminfo: memFree=700804/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=0.03
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 697 2804 0 2 0 0 2 1 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200318 s]
/proc/loadavg: 1.01 1.02 0.96 2/56 23810
/proc/meminfo: memFree=700804/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=0.03
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 697 2804 0 2 0 0 2 1 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300338 s]
/proc/loadavg: 1.01 1.02 0.96 2/56 23810
/proc/meminfo: memFree=700804/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=0.03
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 697 2804 0 2 0 0 2 1 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700287 s]
/proc/loadavg: 1.01 1.02 0.96 2/56 23810
/proc/meminfo: memFree=700804/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=0.03
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 697 2804 0 2 0 0 2 1 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.01 1.02 0.96 2/58 23823
/proc/meminfo: memFree=666432/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=0.03
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 697 2804 0 2 0 0 2 1 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23823] ppid=23810 vsize=49812 CPUtime=1.39
/proc/23823/stat : 23823 (cudf2lp) R 23810 23810 32685 0 -1 4202496 11232 0 0 0 134 5 0 0 20 0 1 0 41424895 51007488 9499 18446744073709551615 4194304 5690517 140733703332192 140733703328392 4963881 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/23823/statm: 12453 9499 160 366 0 12084 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 59024

[startup+3.10034 s]
/proc/loadavg: 1.01 1.02 0.96 2/58 23823
/proc/meminfo: memFree=634564/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=0.03
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 697 2804 0 2 0 0 2 1 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23823] ppid=23810 vsize=93028 CPUtime=2.97
/proc/23823/stat : 23823 (cudf2lp) R 23810 23810 32685 0 -1 4202496 26495 0 0 0 284 13 0 0 20 0 1 0 41424895 95260672 19768 18446744073709551615 4194304 5690517 140733703332192 140733703329832 4293711 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/23823/statm: 23257 19768 160 366 0 22888 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 1.00 1.02 0.96 2/58 23824
/proc/meminfo: memFree=646592/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=5.25
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 725 42124 0 2 0 0 497 28 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23824] ppid=23810 vsize=28460 CPUtime=0.92
/proc/23824/stat : 23824 (gringo) R 23810 23810 32685 0 -1 4202496 7325 0 0 0 83 9 0 0 20 0 1 0 41425425 29143040 6214 18446744073709551615 4194304 6531320 140733729659312 140733729655928 5506488 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23824/statm: 7115 6214 259 571 0 6536 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 37672

[startup+12.7003 s]
/proc/loadavg: 1.00 1.02 0.96 2/58 23824
/proc/meminfo: memFree=373172/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=5.25
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 725 42124 0 2 0 0 497 28 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192298240 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23824] ppid=23810 vsize=388840 CPUtime=7.27
/proc/23824/stat : 23824 (gringo) R 23810 23810 32685 0 -1 4202496 93101 0 0 0 677 50 0 0 20 0 1 0 41425425 398172160 76626 18446744073709551615 4194304 6531320 140733729659312 140733729655736 4595894 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23824/statm: 97210 76626 282 571 0 96631 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 398052

[startup+25.5004 s]
/proc/loadavg: 1.00 1.02 0.96 2/59 23826
/proc/meminfo: memFree=449544/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=238784 CPUtime=5.84
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 71247 0 1 0 557 27 0 0 20 0 1 0 41426843 244514816 58543 18446744073709551615 4194304 6012874 140736447744208 140736447743528 4548198 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 59696 58543 230 444 0 59244 0
[pid=23826] ppid=23810 vsize=22356 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1381 0 10 0 1 1 0 0 20 0 1 0 41426843 22892544 1200 18446744073709551615 4194304 6642060 140735265708032 140735265705992 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5589 1200 508 598 0 675 0
Current children cumulated CPU time (s) 24.99
Current children cumulated vsize (KiB) 270352

[startup+51.1003 s]
/proc/loadavg: 1.00 1.02 0.96 2/59 23826
/proc/meminfo: memFree=449420/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=238784 CPUtime=31.27
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 71247 0 1 0 3099 28 0 0 20 0 1 0 41426843 244514816 58543 18446744073709551615 4194304 6012874 140736447744208 140736447743528 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 59696 58543 230 444 0 59244 0
[pid=23826] ppid=23810 vsize=22536 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1403 0 10 0 1 1 0 0 20 0 1 0 41426843 23076864 1222 18446744073709551615 4194304 6642060 140735265708032 140735265706232 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5634 1222 508 598 0 720 0
Current children cumulated CPU time (s) 50.42
Current children cumulated vsize (KiB) 270532

[startup+102.3 s]
/proc/loadavg: 1.00 1.01 0.96 2/59 23826
/proc/meminfo: memFree=446444/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=238784 CPUtime=82.2
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 71987 0 1 0 8189 31 0 0 20 0 1 0 41426843 244514816 59283 18446744073709551615 4194304 6012874 140736447744208 140736447743528 4548105 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 59696 59283 230 444 0 59244 0
[pid=23826] ppid=23810 vsize=22536 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1403 0 10 0 1 1 0 0 20 0 1 0 41426843 23076864 1222 18446744073709551615 4194304 6642060 140735265708032 140735265706232 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5634 1222 508 598 0 720 0
Current children cumulated CPU time (s) 101.35
Current children cumulated vsize (KiB) 270532

[startup+162.3 s]
/proc/loadavg: 1.00 1.01 0.96 2/63 23841
/proc/meminfo: memFree=443436/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=238784 CPUtime=141.85
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 72057 0 1 0 14152 33 0 0 20 0 1 0 41426843 244514816 59353 18446744073709551615 4194304 6012874 140736447744208 140736447743272 4494997 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 59696 59353 230 444 0 59244 0
[pid=23826] ppid=23810 vsize=22536 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1403 0 10 0 1 1 0 0 20 0 1 0 41426843 23076864 1222 18446744073709551615 4194304 6642060 140735265708032 140735265706232 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5634 1222 508 598 0 720 0
Current children cumulated CPU time (s) 161
Current children cumulated vsize (KiB) 270532

[startup+222.303 s]
/proc/loadavg: 1.00 1.00 0.96 2/63 23841
/proc/meminfo: memFree=409584/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=273424 CPUtime=201.52
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 80584 0 1 0 20113 39 0 0 20 0 1 0 41426843 279986176 67880 18446744073709551615 4194304 6012874 140736447744208 140736447743272 4494944 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 68356 67880 230 444 0 67904 0
[pid=23826] ppid=23810 vsize=22536 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1403 0 10 0 1 1 0 0 20 0 1 0 41426843 23076864 1222 18446744073709551615 4194304 6642060 140735265708032 140735265706232 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5634 1222 508 598 0 720 0
Current children cumulated CPU time (s) 220.67
Current children cumulated vsize (KiB) 305172

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 0.96 2/63 23841
/proc/meminfo: memFree=321048/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=362800 CPUtime=261.19
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 102833 0 1 0 26068 51 0 0 20 0 1 0 41426843 371507200 90129 18446744073709551615 4194304 6012874 140736447744208 140736447743528 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 90700 90129 230 444 0 90248 0
[pid=23826] ppid=23810 vsize=22536 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1403 0 10 0 1 1 0 0 20 0 1 0 41426843 23076864 1222 18446744073709551615 4194304 6642060 140735265708032 140735265706232 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5634 1222 508 598 0 720 0
Current children cumulated CPU time (s) 280.34
Current children cumulated vsize (KiB) 394548



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.1 s]
/proc/loadavg: 1.00 1.00 0.96 2/63 23841
/proc/meminfo: memFree=301580/1022884 swapFree=0/0
[pid=23810] ppid=23809 vsize=9212 CPUtime=19.13
/proc/23810/stat : 23810 (aspuncud-full) S 23809 23810 32685 0 -1 4202496 766 227605 0 2 0 0 1772 141 20 0 1 0 41424888 9433088 365 18446744073709551615 4194304 5129932 140734192299584 140734192297648 139674005333086 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23810/statm: 2303 365 303 229 0 63 0
[pid=23825] ppid=23810 vsize=382020 CPUtime=280.89
/proc/23825/stat : 23825 (unclasp) R 23810 23810 32685 0 -1 4202496 107556 0 1 0 28034 55 0 0 20 0 1 0 41426843 391188480 94852 18446744073709551615 4194304 6012874 140736447744208 140736447743272 4532853 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/23825/statm: 95505 94852 230 444 0 95053 0
[pid=23826] ppid=23810 vsize=22536 CPUtime=0.02
/proc/23826/stat : 23826 (parse.py) S 23810 23810 32685 0 -1 4202496 1403 0 10 0 1 1 0 0 20 0 1 0 41426843 23076864 1222 18446744073709551615 4194304 6642060 140735265708032 140735265706232 140090301900576 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/23826/statm: 5634 1222 508 598 0 720 0
Current children cumulated CPU time (s) 300.04
Current children cumulated vsize (KiB) 413768

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.215
CPU time (s): 300.187
CPU user time (s): 298.147
CPU system time (s): 2.04013
CPU usage (%): 99.3288
Max. virtual memory (cumulated for all children) (KiB): 819032

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.147
system time used= 2.04013
maximum resident set size= 676008
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 337614
page faults= 13
swaps= 0
block input operations= 69472
block output operations= 84288
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 140
involuntary context switches= 4788

runsolver used 0.544034 second user time and 1.13607 second system time

The end