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/slowlink/install/rand411.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand411.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/install/rand411.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

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.93 0.97 0.97 2/59 21318
/proc/meminfo: memFree=444004/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9204 CPUtime=0
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 120588266 9424896 332 18446744073709551615 4194304 5129932 140736495090352 140736495087816 139925532120864 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2301 332 272 229 0 61 0

[startup+0.168363 s]
/proc/loadavg: 0.93 0.97 0.97 2/59 21318
/proc/meminfo: memFree=444004/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=0.02
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 699 2810 0 0 0 0 2 0 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200352 s]
/proc/loadavg: 0.93 0.97 0.97 2/59 21318
/proc/meminfo: memFree=444004/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=0.02
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 699 2810 0 0 0 0 2 0 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300328 s]
/proc/loadavg: 0.93 0.97 0.97 2/59 21318
/proc/meminfo: memFree=444004/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=0.02
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 699 2810 0 0 0 0 2 0 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 0.93 0.97 0.97 2/59 21318
/proc/meminfo: memFree=444004/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=0.02
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 699 2810 0 0 0 0 2 0 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.93 0.97 0.97 1/61 21331
/proc/meminfo: memFree=407408/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=0.02
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 699 2810 0 0 0 0 2 0 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21331] ppid=21318 vsize=50676 CPUtime=1.34
/proc/21331/stat : 21331 (cudf2lp) R 21318 21318 1750 0 -1 4202496 14152 0 0 0 126 8 0 0 20 0 1 0 120588268 51892224 10754 18446744073709551615 4194304 5690517 140735556528256 140735556524840 4951870 0 0 16781316 0 0 0 0 17 0 0 0 11 0 0
/proc/21331/statm: 12669 10754 160 366 0 12300 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 59888

[startup+3.10032 s]
/proc/loadavg: 0.93 0.97 0.97 2/61 21331
/proc/meminfo: memFree=377648/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=0.02
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 699 2810 0 0 0 0 2 0 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21331] ppid=21318 vsize=93028 CPUtime=2.9
/proc/21331/stat : 21331 (cudf2lp) R 21318 21318 1750 0 -1 4202496 26499 0 0 0 278 12 0 0 20 0 1 0 120588268 95260672 19772 18446744073709551615 4194304 5690517 140735556528256 140735556525896 4348966 0 0 16781316 0 0 0 0 17 0 0 0 15 0 0
/proc/21331/statm: 23257 19772 160 366 0 22888 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 102240

[startup+6.30083 s]
/proc/loadavg: 0.93 0.97 0.97 2/61 21332
/proc/meminfo: memFree=387444/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=4.88
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 727 42131 0 0 0 0 464 24 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21332] ppid=21318 vsize=41084 CPUtime=1.18
/proc/21332/stat : 21332 (gringo) R 21318 21318 1750 0 -1 4202496 10408 0 0 0 112 6 0 0 20 0 1 0 120588776 42070016 7276 18446744073709551615 4194304 6531320 140736144614672 140736144610872 5641063 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21332/statm: 10271 7276 259 571 0 9692 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 50296

[startup+12.7003 s]
/proc/loadavg: 0.94 0.97 0.97 2/61 21332
/proc/meminfo: memFree=9096/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=4.88
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 727 42131 0 0 0 0 464 24 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495089008 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21332] ppid=21318 vsize=461408 CPUtime=7.46
/proc/21332/stat : 21332 (gringo) R 21318 21318 1750 0 -1 4202496 110137 0 0 0 694 52 0 0 20 0 1 0 120588776 472481792 100858 18446744073709551615 4194304 6531320 140736144614672 140736144610600 4597961 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21332/statm: 115352 100858 283 571 0 114773 0
Current children cumulated CPU time (s) 12.34
Current children cumulated vsize (KiB) 470620

[startup+25.5004 s]
/proc/loadavg: 0.95 0.97 0.97 2/62 21334
/proc/meminfo: memFree=287692/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=144852 CPUtime=11.57
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 44062 0 0 0 1141 16 0 0 20 0 1 0 120589644 148328448 35754 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 36213 35754 226 444 0 35761 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 24.97
Current children cumulated vsize (KiB) 176108

[startup+51.1003 s]
/proc/loadavg: 1.04 0.99 0.98 2/62 21334
/proc/meminfo: memFree=287692/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=144852 CPUtime=36.97
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 44066 0 0 0 3679 18 0 0 20 0 1 0 120589644 148328448 35758 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 36213 35758 226 444 0 35761 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 50.37
Current children cumulated vsize (KiB) 176108

[startup+102.3 s]
/proc/loadavg: 1.01 0.99 0.98 2/62 21334
/proc/meminfo: memFree=287320/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=144852 CPUtime=87.78
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 44189 0 0 0 8760 18 0 0 20 0 1 0 120589644 148328448 35881 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 36213 35881 226 444 0 35761 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 101.18
Current children cumulated vsize (KiB) 176108

[startup+162.3 s]
/proc/loadavg: 1.03 1.00 0.98 2/62 21334
/proc/meminfo: memFree=199776/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=233964 CPUtime=147.33
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 66113 0 0 0 14703 30 0 0 20 0 1 0 120589644 239579136 57805 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 58491 57805 226 444 0 58039 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 160.73
Current children cumulated vsize (KiB) 265220

[startup+222.303 s]
/proc/loadavg: 1.01 1.00 0.98 2/62 21334
/proc/meminfo: memFree=124384/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=310868 CPUtime=206.88
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 84864 0 0 0 20641 47 0 0 20 0 1 0 120589644 318328832 76556 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4499254 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 77717 76556 226 444 0 77265 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 220.28
Current children cumulated vsize (KiB) 342124

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 21334
/proc/meminfo: memFree=64616/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=377168 CPUtime=266.42
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 99756 0 0 0 26586 56 0 0 20 0 1 0 120589644 386220032 91448 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4499259 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 94292 91448 227 444 0 93840 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 279.82
Current children cumulated vsize (KiB) 408424



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.7 s]
/proc/loadavg: 1.00 1.00 0.98 2/62 21334
/proc/meminfo: memFree=51348/1022884 swapFree=0/0
[pid=21318] ppid=21317 vsize=9212 CPUtime=13.38
/proc/21318/stat : 21318 (aspuncud-full) S 21317 21318 1750 0 -1 4202496 768 157121 0 0 0 0 1244 94 20 0 1 0 120588266 9433088 365 18446744073709551615 4194304 5129932 140736495090352 140736495088416 139925531976798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21318/statm: 2303 365 303 229 0 63 0
[pid=21333] ppid=21318 vsize=390980 CPUtime=286.67
/proc/21333/stat : 21333 (unclasp) R 21318 21318 1750 0 -1 4202496 103069 0 0 0 28609 58 0 0 20 0 1 0 120589644 400363520 94761 18446744073709551615 4194304 6012874 140737133384240 140737133383560 4499254 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21333/statm: 97745 94761 227 444 0 97293 0
[pid=21334] ppid=21318 vsize=22044 CPUtime=0.02
/proc/21334/stat : 21334 (parse.py) S 21318 21318 1750 0 -1 4202496 1324 0 0 0 2 0 0 0 20 0 1 0 120589644 22573056 1132 18446744073709551615 4194304 6642060 140734138759760 140734138757960 139916623062816 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/21334/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 422236

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.755
CPU time (s): 300.147
CPU user time (s): 298.571
CPU system time (s): 1.5761
CPU usage (%): 99.1383
Max. virtual memory (cumulated for all children) (KiB): 492768

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.571
system time used= 1.5761
maximum resident set size= 422828
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262578
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 53032
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 77
involuntary context switches= 34274

runsolver used 0.504031 second user time and 1.16007 second system time

The end