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/rand220.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand220.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/install/rand220.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

[startup+0 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 17449
/proc/meminfo: memFree=502352/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=3152 CPUtime=0
/proc/17449/stat : 17449 (runsolver) R 17448 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119634277 3227648 32 18446744073709551615 134512640 134586868 4289224224 4289222272 4151624752 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.180219 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 17449
/proc/meminfo: memFree=502352/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=0.02
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 695 2808 0 0 0 0 2 0 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200326 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 17449
/proc/meminfo: memFree=502352/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=0.02
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 695 2808 0 0 0 0 2 0 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300317 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 17449
/proc/meminfo: memFree=502352/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=0.02
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 695 2808 0 0 0 0 2 0 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700218 s]
/proc/loadavg: 0.89 0.97 0.95 2/59 17449
/proc/meminfo: memFree=502352/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=0.02
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 695 2808 0 0 0 0 2 0 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50029 s]
/proc/loadavg: 0.89 0.97 0.95 2/61 17462
/proc/meminfo: memFree=465872/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=0.02
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 695 2808 0 0 0 0 2 0 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17462] ppid=17449 vsize=50676 CPUtime=1.41
/proc/17462/stat : 17462 (cudf2lp) R 17449 17449 1750 0 -1 4202496 14503 0 0 0 135 6 0 0 20 0 1 0 119634279 51892224 11105 18446744073709551615 4194304 5690517 140736907566064 140736907563752 5058400 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/17462/statm: 12669 11105 160 366 0 12300 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 59888

[startup+3.10027 s]
/proc/loadavg: 0.89 0.97 0.95 2/61 17462
/proc/meminfo: memFree=414288/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=0.02
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 695 2808 0 0 0 0 2 0 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17462] ppid=17449 vsize=139936 CPUtime=2.98
/proc/17462/stat : 17462 (cudf2lp) R 17449 17449 1750 0 -1 4202496 38943 0 0 0 283 15 0 0 20 0 1 0 119634279 143294464 32216 18446744073709551615 4194304 5690517 140736907566064 140736907563192 4270619 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/17462/statm: 34984 32216 168 366 0 34615 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 149148

[startup+6.30026 s]
/proc/loadavg: 0.90 0.97 0.95 2/61 17463
/proc/meminfo: memFree=377956/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=3.73
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 723 42129 0 0 0 0 352 21 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17463] ppid=17449 vsize=173424 CPUtime=2.45
/proc/17463/stat : 17463 (gringo) R 17449 17449 1750 0 -1 4202496 44190 0 0 0 231 14 0 0 20 0 1 0 119634659 177586176 35908 18446744073709551615 4194304 6531320 140737348199760 140737348196744 4331716 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17463/statm: 43356 35908 278 571 0 42777 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 182636

[startup+12.7003 s]
/proc/loadavg: 0.91 0.97 0.95 1/61 17463
/proc/meminfo: memFree=8380/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=3.73
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 723 42129 0 0 0 0 352 21 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635856 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17463] ppid=17449 vsize=772160 CPUtime=8.33
/proc/17463/stat : 17463 (gringo) R 17449 17449 1750 0 -1 4202496 179601 0 0 0 778 55 0 0 20 0 1 0 119634659 790691840 162475 18446744073709551615 4194304 6531320 140737348199760 140737348197432 4344262 0 0 16781316 16386 0 0 0 17 0 0 0 26 0 0
/proc/17463/statm: 193040 162475 283 571 0 192461 0
Current children cumulated CPU time (s) 12.06
Current children cumulated vsize (KiB) 781372

[startup+25.5003 s]
/proc/loadavg: 0.93 0.97 0.95 2/62 17465
/proc/meminfo: memFree=421820/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=229736 CPUtime=11.85
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 69570 0 18 0 1154 31 0 0 20 0 1 0 119635610 235249664 56971 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4568632 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 57434 56971 230 444 0 56982 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 24.56
Current children cumulated vsize (KiB) 261464

[startup+51.1004 s]
/proc/loadavg: 0.95 0.97 0.95 2/62 17465
/proc/meminfo: memFree=421820/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=229736 CPUtime=37.24
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 69595 0 18 0 3691 33 0 0 20 0 1 0 119635610 235249664 56996 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4498569 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 57434 56996 230 444 0 56982 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 49.95
Current children cumulated vsize (KiB) 261464

[startup+102.3 s]
/proc/loadavg: 1.10 1.00 0.97 2/62 17465
/proc/meminfo: memFree=421696/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=229736 CPUtime=88.05
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 69595 0 18 0 8769 36 0 0 20 0 1 0 119635610 235249664 56996 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 57434 56996 230 444 0 56982 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 100.76
Current children cumulated vsize (KiB) 261464

[startup+162.3 s]
/proc/loadavg: 1.04 1.00 0.97 2/62 17465
/proc/meminfo: memFree=398880/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=253528 CPUtime=147.59
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 75568 0 18 0 14719 40 0 0 20 0 1 0 119635610 259612672 62969 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4532853 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 63382 62969 230 444 0 62930 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 160.3
Current children cumulated vsize (KiB) 285256

[startup+222.303 s]
/proc/loadavg: 1.01 1.00 0.97 2/62 17465
/proc/meminfo: memFree=300796/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=352184 CPUtime=207.13
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 99774 0 18 0 20662 51 0 0 20 0 1 0 119635610 360636416 87175 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4525911 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 88046 87175 230 444 0 87594 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 219.84
Current children cumulated vsize (KiB) 383912

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 0.97 2/62 17465
/proc/meminfo: memFree=215236/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=439908 CPUtime=266.67
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 121217 0 18 0 26604 63 0 0 20 0 1 0 119635610 450465792 108618 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4498569 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 109977 108618 230 444 0 109525 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 279.38
Current children cumulated vsize (KiB) 471636



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.1 s]
/proc/loadavg: 1.00 1.00 0.97 2/62 17465
/proc/meminfo: memFree=190188/1022884 swapFree=0/0
[pid=17449] ppid=17448 vsize=9212 CPUtime=12.69
/proc/17449/stat : 17449 (aspuncud-full) S 17448 17449 1750 0 -1 4202496 764 221734 0 0 0 0 1169 100 20 0 1 0 119634277 9433088 364 18446744073709551615 4194304 5129932 140736848637200 140736848635264 140608951055454 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17449/statm: 2303 364 303 229 0 63 0
[pid=17464] ppid=17449 vsize=465164 CPUtime=287.31
/proc/17464/stat : 17464 (unclasp) R 17449 17449 1750 0 -1 4202496 127358 0 18 0 28665 66 0 0 20 0 1 0 119635610 476327936 114759 18446744073709551615 4194304 6012874 140733875275600 140733875274920 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 20 0 0
/proc/17464/statm: 116291 114759 231 444 0 115839 0
[pid=17465] ppid=17449 vsize=22516 CPUtime=0.02
/proc/17465/stat : 17465 (parse.py) S 17449 17449 1750 0 -1 4202496 1396 0 13 0 2 0 0 0 20 0 1 0 119635610 23056384 1218 18446744073709551615 4194304 6642060 140737159043936 140737159042104 139756236617504 0 0 16777220 20994 0 0 0 17 0 0 0 16 0 0
/proc/17465/statm: 5629 1218 508 598 0 715 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 496892

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.177
CPU time (s): 300.107
CPU user time (s): 298.391
CPU system time (s): 1.71611
CPU usage (%): 98.9874
Max. virtual memory (cumulated for all children) (KiB): 785472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.391
system time used= 1.71611
maximum resident set size= 652504
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 351536
page faults= 32
swaps= 0
block input operations= 91416
block output operations= 82232
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 164
involuntary context switches= 34408

runsolver used 0.544034 second user time and 1.10407 second system time

The end