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/15.runsolver.aptitude aptitude -s -y --without-recommends install gql-shell libarchive-tar-perl harden-servers xara-gtk-byte libgnome2-doc 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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.17 1.10 0.82 2/55 20948 /proc/meminfo: memFree=907172/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=54860 CPUtime=0 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 592 0 0 0 0 0 0 0 20 0 1 0 28320342 56176640 492 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644051800 140002806719607 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 13715 492 403 1052 0 73 0 [startup+0.14382 s] /proc/loadavg: 1.17 1.10 0.82 2/55 20948 /proc/meminfo: memFree=907172/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=89152 CPUtime=0.13 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 7772 1709 0 0 12 1 0 0 20 0 1 0 28320342 91291648 7572 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644043856 140002766446301 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 22288 7572 6662 1052 0 858 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 89152 [startup+0.200287 s] /proc/loadavg: 1.17 1.10 0.82 2/55 20948 /proc/meminfo: memFree=907172/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=89152 CPUtime=0.19 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 7776 1709 0 0 18 1 0 0 20 0 1 0 28320342 91291648 7576 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644043856 140002803709701 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 22288 7576 6666 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300271 s] /proc/loadavg: 1.17 1.10 0.82 2/55 20948 /proc/meminfo: memFree=907172/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=100164 CPUtime=0.29 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 11280 1709 0 0 26 3 0 0 20 0 1 0 28320342 102567936 10326 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644042104 140002811803533 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 25041 10326 6742 1052 0 3611 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 100164 [startup+0.700214 s] /proc/loadavg: 1.17 1.10 0.82 2/55 20948 /proc/meminfo: memFree=907172/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=114088 CPUtime=0.68 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 13698 1709 0 0 64 4 0 0 20 0 2 0 28320342 116826112 12070 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644043864 140002766364981 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 28522 12070 6977 1052 0 7092 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 114088 [startup+1.50024 s] /proc/loadavg: 1.17 1.10 0.82 2/57 20953 /proc/meminfo: memFree=886464/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=115468 CPUtime=1.48 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 14517 2207 0 0 142 6 0 0 20 0 2 0 28320342 118239232 12297 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644039296 140002774778880 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 28867 12297 7066 1052 0 7437 0 [pid=20948/tid=20953] ppid=20947 vsize=115468 CPUtime=0 /proc/20948/task/20953/stat : 20953 (aptitude) S 20947 20948 17863 34816 17863 4202560 6 2207 0 0 0 0 0 0 20 0 2 0 28320387 118239232 12297 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712270848 140002777608916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 115468 [startup+3.10025 s] /proc/loadavg: 1.17 1.10 0.82 2/57 20954 /proc/meminfo: memFree=877288/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=211636 CPUtime=3.07 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 23493 2207 0 0 297 10 0 0 20 0 2 0 28320342 216715264 20228 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 52909 20228 7122 1052 0 31479 0 [pid=20948/tid=20953] ppid=20947 vsize=211636 CPUtime=1.2 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 8950 2207 0 0 116 4 0 0 20 0 2 0 28320387 216715264 20228 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712260280 140002811497690 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 211636 [startup+6.30024 s] /proc/loadavg: 1.15 1.10 0.83 2/57 20954 /proc/meminfo: memFree=829548/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=240876 CPUtime=6.25 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 30823 2207 0 0 610 15 0 0 20 0 2 0 28320342 246657024 27557 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 60219 27557 7122 1052 0 38789 0 [pid=20948/tid=20953] ppid=20947 vsize=240876 CPUtime=4.38 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 16280 2207 0 0 429 9 0 0 20 0 2 0 28320387 246657024 27557 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712264376 140002811561858 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.25 Current children cumulated vsize (KiB) 240876 [startup+12.7002 s] /proc/loadavg: 1.14 1.09 0.83 2/57 20954 /proc/meminfo: memFree=774864/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=295212 CPUtime=12.62 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 44418 2207 0 0 1240 22 0 0 20 0 2 0 28320342 302297088 41121 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 73803 41121 7124 1052 0 52373 0 [pid=20948/tid=20953] ppid=20947 vsize=295212 CPUtime=10.75 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 29875 2207 0 0 1059 16 0 0 20 0 2 0 28320387 302297088 41121 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712261816 140002803688569 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.62 Current children cumulated vsize (KiB) 295212 [startup+25.5003 s] /proc/loadavg: 1.11 1.09 0.83 2/57 20954 /proc/meminfo: memFree=701704/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=365292 CPUtime=25.36 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 61912 2207 0 0 2498 38 0 0 20 0 2 0 28320342 374059008 58615 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 91323 58615 7124 1052 0 69893 0 [pid=20948/tid=20953] ppid=20947 vsize=365292 CPUtime=23.5 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 47369 2207 0 0 2318 32 0 0 20 0 2 0 28320387 374059008 58615 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712264280 140002811075677 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 365292 [startup+51.1003 s] /proc/loadavg: 1.07 1.08 0.83 2/57 20954 /proc/meminfo: memFree=559104/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=509564 CPUtime=50.85 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 97962 2207 0 0 5024 61 0 0 20 0 2 0 28320342 521793536 94665 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 127391 94665 7138 1052 0 105961 0 [pid=20948/tid=20953] ppid=20947 vsize=509564 CPUtime=48.98 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 83413 2207 0 0 4843 55 0 0 20 0 2 0 28320387 521793536 94665 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712262216 140002809510194 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 509564 [startup+102.3 s] /proc/loadavg: 1.03 1.07 0.83 2/57 20954 /proc/meminfo: memFree=262868/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=802008 CPUtime=101.82 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 171009 2207 0 0 10083 99 0 0 20 0 2 0 28320342 821256192 167712 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 200502 167712 7138 1052 0 179072 0 [pid=20948/tid=20953] ppid=20947 vsize=802008 CPUtime=99.95 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 156460 2207 0 0 9902 93 0 0 20 0 2 0 28320387 821256192 167712 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712262344 140002766375239 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.82 Current children cumulated vsize (KiB) 802008 Solver just ended. Dumping a history of the last processes samples [startup+102.407 s] /proc/loadavg: 1.03 1.07 0.83 2/57 20954 /proc/meminfo: memFree=262868/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=802536 CPUtime=101.92 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 171143 2207 0 0 10093 99 0 0 20 0 2 0 28320342 821796864 167846 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 200634 167846 7138 1052 0 179204 0 [pid=20948/tid=20953] ppid=20947 vsize=802536 CPUtime=100.05 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 156594 2207 0 0 9912 93 0 0 20 0 2 0 28320387 821796864 167846 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712262216 140002811093722 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 101.92 Current children cumulated vsize (KiB) 802536 [startup+128 s] /proc/loadavg: 1.02 1.06 0.84 2/57 20954 /proc/meminfo: memFree=67816/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=999528 CPUtime=127.39 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 220119 2207 0 0 12611 128 0 0 20 0 2 0 28320342 1023516672 216822 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 249882 216822 7138 1052 0 228452 0 [pid=20948/tid=20953] ppid=20947 vsize=999528 CPUtime=125.52 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 205570 2207 0 0 12430 122 0 0 20 0 2 0 28320387 1023516672 216822 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712263272 140002811378139 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) 999528 [startup+134.4 s] /proc/loadavg: 1.02 1.06 0.84 2/57 20954 /proc/meminfo: memFree=29500/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=1036832 CPUtime=133.77 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 229482 2207 0 0 13244 133 0 0 20 0 2 0 28320342 1061715968 226185 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 259208 226185 7138 1052 0 237778 0 [pid=20948/tid=20953] ppid=20947 vsize=1036832 CPUtime=131.89 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 214933 2207 0 0 13062 127 0 0 20 0 2 0 28320387 1061715968 226185 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712264424 140002766360393 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 133.77 Current children cumulated vsize (KiB) 1036832 [startup+137.607 s] /proc/loadavg: 1.02 1.06 0.84 2/57 20954 /proc/meminfo: memFree=8420/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=1057820 CPUtime=136.94 /proc/20948/stat : 20948 (aptitude) S 20947 20948 17863 34816 17863 4202496 234734 2207 0 0 13558 136 0 0 20 0 2 0 28320342 1083207680 231437 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644044352 140002777609803 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/20948/statm: 264455 231437 7138 1052 0 243025 0 [pid=20948/tid=20953] ppid=20947 vsize=1057820 CPUtime=135.07 /proc/20948/task/20953/stat : 20953 (aptitude) R 20947 20948 17863 34816 17863 4202560 220185 2207 0 0 13377 130 0 0 20 0 2 0 28320387 1083207680 231437 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712260376 140002811563587 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 136.94 Current children cumulated vsize (KiB) 1057820 [startup+140.8 s] /proc/loadavg: 1.09 1.07 0.84 2/57 20954 /proc/meminfo: memFree=10028/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=1064944 CPUtime=140.06 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 236637 2207 5 0 13868 138 0 0 20 0 2 0 28320342 1090502656 233199 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644042888 140002766356050 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0 /proc/20948/statm: 266236 233199 7166 1052 0 244799 0 [pid=20948/tid=20953] ppid=20947 vsize=1064944 CPUtime=136.74 /proc/20948/task/20953/stat : 20953 (aptitude) S 20947 20948 17863 34816 17863 4202560 221944 2207 0 0 13542 132 0 0 20 0 2 0 28320387 1090502656 233199 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712270848 140002777608916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 140.06 Current children cumulated vsize (KiB) 1064944 [startup+141.6 s] /proc/loadavg: 1.09 1.07 0.84 2/57 20954 /proc/meminfo: memFree=10028/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=1064944 CPUtime=140.85 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 236637 2207 5 0 13947 138 0 0 20 0 2 0 28320342 1090502656 233199 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644042888 140002766355896 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 2 0 0 /proc/20948/statm: 266236 233199 7166 1052 0 244799 0 [pid=20948/tid=20953] ppid=20947 vsize=1064944 CPUtime=136.74 /proc/20948/task/20953/stat : 20953 (aptitude) S 20947 20948 17863 34816 17863 4202560 221944 2207 0 0 13542 132 0 0 20 0 2 0 28320387 1090502656 233199 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712270848 140002777608916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 140.85 Current children cumulated vsize (KiB) 1064944 [startup+142.007 s] /proc/loadavg: 1.09 1.07 0.84 2/57 20954 /proc/meminfo: memFree=9276/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=1064944 CPUtime=141.14 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 238505 2207 20 0 13961 153 0 0 20 0 2 0 28320342 1090502656 233319 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644042352 140002766567734 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 13 0 0 /proc/20948/statm: 266236 233319 7187 1052 0 244799 0 [pid=20948/tid=20953] ppid=20947 vsize=1064944 CPUtime=136.74 /proc/20948/task/20953/stat : 20953 (aptitude) S 20947 20948 17863 34816 17863 4202560 221944 2207 0 0 13542 132 0 0 20 0 2 0 28320387 1090502656 233319 18446744073709551615 140002808864768 140002813172120 140734644052592 140002712270848 140002777608916 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 141.14 Current children cumulated vsize (KiB) 1064944 [startup+142.405 s] /proc/loadavg: 1.09 1.07 0.84 2/57 20954 /proc/meminfo: memFree=9276/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=928684 CPUtime=141.32 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 238879 2696 51 10 13964 165 1 2 20 0 1 0 28320342 950972416 133666 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644052152 140002766730730 0 134217728 4096 0 0 0 0 17 0 0 0 20 0 0 /proc/20948/statm: 232171 133666 1516 1052 0 216427 0 Current children cumulated CPU time (s) 141.32 Current children cumulated vsize (KiB) 928684 [startup+142.501 s] /proc/loadavg: 1.09 1.07 0.84 2/57 20954 /proc/meminfo: memFree=9276/1022884 swapFree=0/0 [pid=20948] ppid=20947 vsize=928684 CPUtime=141.41 /proc/20948/stat : 20948 (aptitude) R 20947 20948 17863 34816 17863 4202496 238879 2696 51 10 13964 174 1 2 20 0 1 0 28320342 950972416 30242 18446744073709551615 140002808864768 140002813172120 140734644052592 140734644052152 140002766730730 0 134217728 4096 0 0 0 0 17 0 0 0 20 0 0 /proc/20948/statm: 232171 30242 1516 1052 0 216427 0 Current children cumulated CPU time (s) 141.41 Current children cumulated vsize (KiB) 928684 Child status: 0 Real time (s): 142.532 CPU time (s): 141.453 CPU user time (s): 139.653 CPU system time (s): 1.80011 CPU usage (%): 99.2431 Max. virtual memory (cumulated for all children) (KiB): 1064944 getrusage(RUSAGE_CHILDREN,...) data: user time used= 139.653 system time used= 1.80011 maximum resident set size= 933276 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 241666 page faults= 64 swaps= 0 block input operations= 3696 block output operations= 56 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 426 involuntary context switches= 2542 runsolver used 0.16801 second user time and 0.48003 second system time The end