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 -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny/logs/99.runsolver.aptitude aptitude -s -y --without-recommends install filter njplot kgpg screem python2.2-musicbrainz Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 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: 1.04 1.04 1.00 2/55 22187 /proc/meminfo: memFree=909928/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=3152 CPUtime=0 /proc/22187/stat : 22187 (runsolver) R 22186 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28658199 3227648 32 18446744073709551615 134512640 134586868 4289773376 4289771424 4152087600 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22187/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.18182 s] /proc/loadavg: 1.04 1.04 1.00 2/55 22187 /proc/meminfo: memFree=909928/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=89152 CPUtime=0.16 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 7775 1709 0 0 15 1 0 0 20 0 1 0 28658199 91291648 7576 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772016 140374870742765 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22187/statm: 22288 7576 6665 1052 0 858 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 89152 [startup+0.200296 s] /proc/loadavg: 1.04 1.04 1.00 2/55 22187 /proc/meminfo: memFree=909928/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=89152 CPUtime=0.18 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 7869 1709 0 0 17 1 0 0 20 0 1 0 28658199 91291648 7662 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867770528 140374870754967 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22187/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 89152 [startup+0.300266 s] /proc/loadavg: 1.04 1.04 1.00 2/55 22187 /proc/meminfo: memFree=909928/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=101864 CPUtime=0.28 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 11708 1709 0 0 26 2 0 0 20 0 1 0 28658199 104308736 10756 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867770184 140374870806676 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22187/statm: 25466 10756 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 101864 [startup+0.700212 s] /proc/loadavg: 1.04 1.04 1.00 2/55 22187 /proc/meminfo: memFree=909928/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=108532 CPUtime=0.68 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 12258 1709 0 0 64 4 0 0 20 0 2 0 28658199 111136768 10632 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867776248 140374878037312 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22187/statm: 27133 10632 6925 1052 0 5703 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 108532 [startup+1.50024 s] /proc/loadavg: 1.04 1.04 1.00 2/57 22192 /proc/meminfo: memFree=888964/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=115480 CPUtime=1.46 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 14141 2208 0 0 138 8 0 0 20 0 2 0 28658199 118251520 12366 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772352 140374844662157 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 28870 12366 7057 1052 0 7440 0 [pid=22187/tid=22192] ppid=22186 vsize=115480 CPUtime=0 /proc/22187/task/22192/stat : 22192 (aptitude) S 22186 22187 17863 34816 17863 4202560 4 2208 0 0 0 0 0 0 20 0 2 0 28658243 118251520 12366 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779312128 140374844650196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.46 Current children cumulated vsize (KiB) 115480 [startup+3.10024 s] /proc/loadavg: 1.04 1.04 1.00 2/57 22193 /proc/meminfo: memFree=882268/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=198048 CPUtime=3.06 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 19414 2208 0 0 295 11 0 0 20 0 2 0 28658199 202801152 16862 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 49512 16862 7128 1052 0 28082 0 [pid=22187/tid=22192] ppid=22186 vsize=198048 CPUtime=1.01 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 4707 2208 0 0 100 1 0 0 20 0 2 0 28658243 202801152 16862 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779305656 140374878552346 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.06 Current children cumulated vsize (KiB) 198048 [startup+6.30024 s] /proc/loadavg: 1.04 1.04 1.00 2/57 22193 /proc/meminfo: memFree=851888/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=225276 CPUtime=6.24 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 26313 2208 0 0 612 12 0 0 20 0 2 0 28658199 230682624 23649 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 56319 23649 7129 1052 0 34889 0 [pid=22187/tid=22192] ppid=22186 vsize=225276 CPUtime=4.19 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 11606 2208 0 0 416 3 0 0 20 0 2 0 28658243 230682624 23649 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303400 140374878604892 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.24 Current children cumulated vsize (KiB) 225276 [startup+12.7002 s] /proc/loadavg: 1.04 1.04 1.00 2/57 22193 /proc/meminfo: memFree=794600/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=278688 CPUtime=12.61 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 39992 2208 0 0 1244 17 0 0 20 0 2 0 28658199 285376512 37002 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 69672 37002 7129 1052 0 48242 0 [pid=22187/tid=22192] ppid=22186 vsize=278688 CPUtime=10.57 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 25285 2208 0 0 1049 8 0 0 20 0 2 0 28658243 285376512 37002 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303448 140374833416478 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.61 Current children cumulated vsize (KiB) 278688 [startup+25.5003 s] /proc/loadavg: 1.03 1.04 1.00 2/57 22193 /proc/meminfo: memFree=699740/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=370032 CPUtime=25.35 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 62804 2208 0 0 2503 32 0 0 20 0 2 0 28658199 378912768 59814 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 92508 59814 7129 1052 0 71078 0 [pid=22187/tid=22192] ppid=22186 vsize=370032 CPUtime=23.31 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 48097 2208 0 0 2308 23 0 0 20 0 2 0 28658243 378912768 59814 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303448 140374878708376 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.35 Current children cumulated vsize (KiB) 370032 [startup+51.1003 s] /proc/loadavg: 1.02 1.03 1.00 2/57 22193 /proc/meminfo: memFree=539780/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=531160 CPUtime=50.83 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 103054 2208 0 0 5032 51 0 0 20 0 2 0 28658199 543907840 100063 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 132790 100063 7129 1052 0 111360 0 [pid=22187/tid=22192] ppid=22186 vsize=531160 CPUtime=48.79 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 88347 2208 0 0 4837 42 0 0 20 0 2 0 28658243 543907840 100063 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779305656 140374834058451 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 531160 [startup+102.3 s] /proc/loadavg: 1.00 1.03 1.00 2/57 22193 /proc/meminfo: memFree=285828/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=781976 CPUtime=101.81 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 165802 2208 0 0 10097 84 0 0 20 0 2 0 28658199 800743424 162670 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 195494 162670 7143 1052 0 174064 0 [pid=22187/tid=22192] ppid=22186 vsize=781976 CPUtime=99.75 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 151088 2208 0 0 9901 74 0 0 20 0 2 0 28658243 800743424 162670 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303400 140374834116530 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.81 Current children cumulated vsize (KiB) 781976 Solver just ended. Dumping a history of the last processes samples [startup+102.403 s] /proc/loadavg: 1.00 1.03 1.00 2/57 22193 /proc/meminfo: memFree=285828/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=782240 CPUtime=101.91 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 165869 2208 0 0 10107 84 0 0 20 0 2 0 28658199 801013760 162737 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 195560 162737 7143 1052 0 174130 0 [pid=22187/tid=22192] ppid=22186 vsize=782240 CPUtime=99.86 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 151155 2208 0 0 9911 75 0 0 20 0 2 0 28658243 801013760 162737 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303400 140374878519901 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 782240 [startup+128 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=200640/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=868352 CPUtime=127.39 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 187504 2208 0 0 12637 102 0 0 20 0 2 0 28658199 889192448 184268 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 217088 184268 7143 1052 0 195658 0 [pid=22187/tid=22192] ppid=22186 vsize=868352 CPUtime=125.33 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 172790 2208 0 0 12441 92 0 0 20 0 2 0 28658243 889192448 184268 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303448 140374844641646 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 127.39 Current children cumulated vsize (KiB) 868352 [startup+140.8 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=148188/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=919116 CPUtime=140.13 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 200222 2208 0 0 13905 108 0 0 20 0 2 0 28658199 941174784 196981 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 229779 196981 7143 1052 0 208349 0 [pid=22187/tid=22192] ppid=22186 vsize=919116 CPUtime=138.08 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 185508 2208 0 0 13709 99 0 0 20 0 2 0 28658243 941174784 196981 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303448 140374878582297 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 140.13 Current children cumulated vsize (KiB) 919116 [startup+147.2 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=126488/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=944412 CPUtime=146.51 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 206535 2208 0 0 14540 111 0 0 20 0 2 0 28658199 967077888 203294 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 236103 203294 7143 1052 0 214673 0 [pid=22187/tid=22192] ppid=22186 vsize=944412 CPUtime=144.46 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 191821 2208 0 0 14344 102 0 0 20 0 2 0 28658243 967077888 203294 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303448 140374878582297 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 146.51 Current children cumulated vsize (KiB) 944412 [startup+150.4 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=113344/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=957556 CPUtime=149.69 /proc/22187/stat : 22187 (aptitude) S 22186 22187 17863 34816 17863 4202496 209840 2208 0 0 14857 112 0 0 20 0 2 0 28658199 980537344 206599 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772512 140374844651083 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 239389 206599 7143 1052 0 217959 0 [pid=22187/tid=22192] ppid=22186 vsize=957556 CPUtime=147.64 /proc/22187/task/22192/stat : 22192 (aptitude) R 22186 22187 17863 34816 17863 4202560 195126 2208 0 0 14661 103 0 0 20 0 2 0 28658243 980537344 206599 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779303624 140374878552442 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 149.69 Current children cumulated vsize (KiB) 957556 [startup+152 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=103796/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=963816 CPUtime=151.28 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 211741 2208 0 0 15015 113 0 0 20 0 2 0 28658199 986947584 208366 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867770888 140374878532736 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 240954 208366 7191 1052 0 219517 0 [pid=22187/tid=22192] ppid=22186 vsize=963816 CPUtime=149.11 /proc/22187/task/22192/stat : 22192 (aptitude) S 22186 22187 17863 34816 17863 4202560 196673 2208 0 0 14807 104 0 0 20 0 2 0 28658243 986947584 208366 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779312128 140374844650196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 151.28 Current children cumulated vsize (KiB) 963816 [startup+153.6 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=102308/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=963912 CPUtime=152.87 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 211776 2208 0 0 15174 113 0 0 20 0 2 0 28658199 987045888 208401 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867770888 140374833397419 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 240978 208401 7191 1052 0 219541 0 [pid=22187/tid=22192] ppid=22186 vsize=963912 CPUtime=149.11 /proc/22187/task/22192/stat : 22192 (aptitude) S 22186 22187 17863 34816 17863 4202560 196673 2208 0 0 14807 104 0 0 20 0 2 0 28658243 987045888 208401 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779312128 140374844650196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 152.87 Current children cumulated vsize (KiB) 963912 [startup+154.4 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=102308/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=963912 CPUtime=153.67 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 213788 2208 0 0 15254 113 0 0 20 0 2 0 28658199 987045888 208348 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867772568 140374834058463 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 240978 208348 7192 1052 0 219541 0 [pid=22187/tid=22192] ppid=22186 vsize=963912 CPUtime=149.11 /proc/22187/task/22192/stat : 22192 (aptitude) S 22186 22187 17863 34816 17863 4202560 196673 2208 0 0 14807 104 0 0 20 0 2 0 28658243 987045888 208348 18446744073709551615 140374875906048 140374880213400 140733867780752 140374779312128 140374844650196 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 153.67 Current children cumulated vsize (KiB) 963912 [startup+154.801 s] /proc/loadavg: 1.00 1.02 1.00 2/57 22193 /proc/meminfo: memFree=102308/1022884 swapFree=0/0 [pid=22187] ppid=22186 vsize=586592 CPUtime=154.08 /proc/22187/stat : 22187 (aptitude) R 22186 22187 17863 34816 17863 4202496 214616 2708 0 0 15258 148 0 2 20 0 1 0 28658199 600670208 21055 18446744073709551615 140374875906048 140374880213400 140733867780752 140733867780312 140374833772010 0 134217728 4096 0 0 0 0 17 0 0 0 1 0 0 /proc/22187/statm: 146648 21055 1521 1052 0 130904 0 Current children cumulated CPU time (s) 154.08 Current children cumulated vsize (KiB) 586592 Child status: 0 Real time (s): 154.82 CPU time (s): 154.114 CPU user time (s): 152.59 CPU system time (s): 1.52409 CPU usage (%): 99.5434 Max. virtual memory (cumulated for all children) (KiB): 963912 getrusage(RUSAGE_CHILDREN,...) data: user time used= 152.59 system time used= 1.52409 maximum resident set size= 833968 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 217391 page faults= 0 swaps= 0 block input operations= 0 block output operations= 168 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 367 involuntary context switches= 2641 runsolver used 0.180011 second user time and 0.520032 second system time The end