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/54.runsolver.aptitude aptitude -s -y --without-recommends install gtk2-engines-industrial scripts4ticker heroes-sound-tracks xfonts-intl-chinese-big ksimus-boolean 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.01 1.02 0.94 2/55 21549 /proc/meminfo: memFree=855400/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=3152 CPUtime=0 /proc/21549/stat : 21549 (runsolver) R 21548 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28459912 3227648 33 18446744073709551615 134512640 134586868 4291871968 4291870016 4151514160 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.183246 s] /proc/loadavg: 1.01 1.02 0.94 2/55 21549 /proc/meminfo: memFree=855400/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=89152 CPUtime=0.17 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 7777 1709 0 0 15 2 0 0 20 0 1 0 28459912 91291648 7576 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267280 140151024450215 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 22288 7576 6665 1052 0 858 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 89152 [startup+0.20028 s] /proc/loadavg: 1.01 1.02 0.94 2/55 21549 /proc/meminfo: memFree=855400/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=89152 CPUtime=0.19 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 7871 1709 0 0 17 2 0 0 20 0 1 0 28459912 91291648 7662 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396265792 140151062111441 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300267 s] /proc/loadavg: 1.01 1.02 0.94 2/55 21549 /proc/meminfo: memFree=855400/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=101864 CPUtime=0.28 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 11710 1709 0 0 26 2 0 0 20 0 1 0 28459912 104308736 10756 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396265448 140151062163568 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 25466 10756 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 101864 [startup+0.700206 s] /proc/loadavg: 1.01 1.02 0.94 2/55 21549 /proc/meminfo: memFree=855400/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=108532 CPUtime=0.68 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 12276 1709 0 0 65 3 0 0 20 0 2 0 28459912 111136768 10649 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396271512 140151033191563 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 27133 10649 6943 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.01 1.02 0.94 2/57 21554 /proc/meminfo: memFree=834436/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=115472 CPUtime=1.48 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 14189 2207 0 0 140 8 0 0 20 0 2 0 28459912 118243328 12396 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396266728 140151069097638 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 28868 12396 7071 1052 0 7438 0 [pid=21549/tid=21554] ppid=21548 vsize=115472 CPUtime=0 /proc/21549/task/21554/stat : 21554 (aptitude) S 21548 21549 17863 34816 17863 4202560 4 2207 0 0 0 0 0 0 20 0 2 0 28459956 118243328 12396 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970669056 140151036007124 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) 115472 [startup+3.10024 s] /proc/loadavg: 1.01 1.02 0.94 2/57 21555 /proc/meminfo: memFree=827616/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=132640 CPUtime=3.07 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 19431 2207 0 0 296 11 0 0 20 0 2 0 28459912 135823360 16874 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 33160 16874 7129 1052 0 11730 0 [pid=21549/tid=21554] ppid=21548 vsize=132640 CPUtime=1.02 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 4729 2207 0 0 99 3 0 0 20 0 2 0 28459956 135823360 16874 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970662584 140151069896032 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) 132640 [startup+6.30024 s] /proc/loadavg: 1.01 1.02 0.94 2/57 21555 /proc/meminfo: memFree=797732/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=224844 CPUtime=6.25 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 26203 2207 0 0 610 15 0 0 20 0 2 0 28459912 230240256 23532 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 56211 23532 7129 1052 0 34781 0 [pid=21549/tid=21554] ppid=21548 vsize=224844 CPUtime=4.21 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 11500 2207 0 0 414 7 0 0 20 0 2 0 28459956 230240256 23532 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970662632 140151069939225 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) 224844 [startup+12.7002 s] /proc/loadavg: 1.01 1.02 0.94 2/57 21555 /proc/meminfo: memFree=740816/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=278468 CPUtime=12.63 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 39922 2207 0 0 1242 21 0 0 20 0 2 0 28459912 285151232 36926 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 69617 36926 7129 1052 0 48187 0 [pid=21549/tid=21554] ppid=21548 vsize=278468 CPUtime=10.58 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 25219 2207 0 0 1045 13 0 0 20 0 2 0 28459956 285151232 36926 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970660376 140151036003886 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 278468 [startup+25.5002 s] /proc/loadavg: 1.00 1.01 0.94 2/57 21555 /proc/meminfo: memFree=643476/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=372008 CPUtime=25.37 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 63306 2207 0 0 2500 37 0 0 20 0 2 0 28459912 380936192 60310 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 93002 60310 7129 1052 0 71572 0 [pid=21549/tid=21554] ppid=21548 vsize=372008 CPUtime=23.32 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 48603 2207 0 0 2303 29 0 0 20 0 2 0 28459956 380936192 60310 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970662584 140151069859664 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.37 Current children cumulated vsize (KiB) 372008 [startup+51.1003 s] /proc/loadavg: 1.00 1.01 0.94 2/57 21555 /proc/meminfo: memFree=484632/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=531956 CPUtime=50.84 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 103252 2207 0 0 5031 53 0 0 20 0 2 0 28459912 544722944 100247 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 132989 100247 7129 1052 0 111559 0 [pid=21549/tid=21554] ppid=21548 vsize=531956 CPUtime=48.8 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 88549 2207 0 0 4835 45 0 0 20 0 2 0 28459956 544722944 100247 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970660328 140151069464347 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 50.84 Current children cumulated vsize (KiB) 531956 [startup+102.3 s] /proc/loadavg: 1.00 1.01 0.94 2/57 21555 /proc/meminfo: memFree=229936/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=783716 CPUtime=101.82 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 166222 2207 0 0 10099 83 0 0 20 0 2 0 28459912 802525184 163094 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 195929 163094 7143 1052 0 174499 0 [pid=21549/tid=21554] ppid=21548 vsize=783716 CPUtime=99.77 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 151512 2207 0 0 9902 75 0 0 20 0 2 0 28459956 802525184 163094 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970660376 140151069473885 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) 783716 Solver just ended. Dumping a history of the last processes samples [startup+102.403 s] /proc/loadavg: 1.00 1.01 0.94 2/57 21555 /proc/meminfo: memFree=229936/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=783980 CPUtime=101.91 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 166296 2207 0 0 10108 83 0 0 20 0 2 0 28459912 802795520 163168 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 195995 163168 7143 1052 0 174565 0 [pid=21549/tid=21554] ppid=21548 vsize=783980 CPUtime=99.86 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 151586 2207 0 0 9911 75 0 0 20 0 2 0 28459956 802795520 163168 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970662584 140151068613120 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) 783980 [startup+128 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=144500/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=870456 CPUtime=127.39 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 188044 2207 0 0 12643 96 0 0 20 0 2 0 28459912 891346944 184807 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 217614 184807 7143 1052 0 196184 0 [pid=21549/tid=21554] ppid=21548 vsize=870456 CPUtime=125.34 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 173334 2207 0 0 12446 88 0 0 20 0 2 0 28459956 891346944 184807 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970660376 140151024773447 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) 870456 [startup+140.8 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=90064/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=923208 CPUtime=140.14 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 201231 2207 0 0 13908 106 0 0 20 0 2 0 28459912 945364992 197991 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 230802 197991 7143 1052 0 209372 0 [pid=21549/tid=21554] ppid=21548 vsize=923208 CPUtime=138.09 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 186521 2207 0 0 13711 98 0 0 20 0 2 0 28459956 945364992 197991 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970660376 140151069961756 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 140.14 Current children cumulated vsize (KiB) 923208 [startup+147.2 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=67372/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=949728 CPUtime=146.51 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 207867 2207 0 0 14542 109 0 0 20 0 2 0 28459912 972521472 204627 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396267776 140151036008011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 237432 204627 7143 1052 0 216002 0 [pid=21549/tid=21554] ppid=21548 vsize=949728 CPUtime=144.45 /proc/21549/task/21554/stat : 21554 (aptitude) R 21548 21549 17863 34816 17863 4202560 193157 2207 0 0 14344 101 0 0 20 0 2 0 28459956 972521472 204627 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970660328 140151070065304 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) 949728 [startup+148.8 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=58196/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=953740 CPUtime=148.1 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 209233 2207 0 0 14700 110 0 0 20 0 2 0 28459912 976629760 205860 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396266152 140151024773143 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 238435 205860 7191 1052 0 216998 0 [pid=21549/tid=21554] ppid=21548 vsize=953740 CPUtime=145.41 /proc/21549/task/21554/stat : 21554 (aptitude) S 21548 21549 17863 34816 17863 4202560 194170 2207 0 0 14440 101 0 0 20 0 2 0 28459956 976629760 205860 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970669056 140151036007124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 148.1 Current children cumulated vsize (KiB) 953740 [startup+150.4 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=58196/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=953832 CPUtime=149.7 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 209758 2207 0 0 14860 110 0 0 20 0 2 0 28459912 976723968 205896 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396266104 140151068091952 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 238458 205896 7192 1052 0 217021 0 [pid=21549/tid=21554] ppid=21548 vsize=953832 CPUtime=145.41 /proc/21549/task/21554/stat : 21554 (aptitude) S 21548 21549 17863 34816 17863 4202560 194170 2207 0 0 14440 101 0 0 20 0 2 0 28459956 976723968 205896 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970669056 140151036007124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 149.7 Current children cumulated vsize (KiB) 953832 [startup+150.807 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=57444/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=953832 CPUtime=150.09 /proc/21549/stat : 21549 (aptitude) S 21548 21549 17863 34816 17863 4202496 211271 2207 0 0 14884 125 0 0 20 0 2 0 28459912 976723968 205871 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396265792 140151025131987 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 238458 205871 7192 1052 0 217021 0 [pid=21549/tid=21554] ppid=21548 vsize=953832 CPUtime=145.41 /proc/21549/task/21554/stat : 21554 (aptitude) S 21548 21549 17863 34816 17863 4202560 194170 2207 0 0 14440 101 0 0 20 0 2 0 28459956 976723968 205871 18446744073709551615 140151067262976 140151071570328 140736396276016 140150970669056 140151036007124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 150.09 Current children cumulated vsize (KiB) 953832 [startup+151.001 s] /proc/loadavg: 1.00 1.00 0.94 2/57 21555 /proc/meminfo: memFree=57444/1022884 swapFree=0/0 [pid=21549] ppid=21548 vsize=599076 CPUtime=150.3 /proc/21549/stat : 21549 (aptitude) R 21548 21549 17863 34816 17863 4202496 212066 2706 0 0 14888 140 0 2 20 0 1 0 28459912 613453824 49662 18446744073709551615 140151067262976 140151071570328 140736396276016 140736396275576 140151025128938 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21549/statm: 149769 49662 1521 1052 0 134025 0 Current children cumulated CPU time (s) 150.3 Current children cumulated vsize (KiB) 599076 Child status: 0 Real time (s): 151.047 CPU time (s): 150.361 CPU user time (s): 148.889 CPU system time (s): 1.47209 CPU usage (%): 99.5458 Max. virtual memory (cumulated for all children) (KiB): 953832 getrusage(RUSAGE_CHILDREN,...) data: user time used= 148.889 system time used= 1.47209 maximum resident set size= 823940 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 214839 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= 359 involuntary context switches= 2571 runsolver used 0.17201 second user time and 0.520032 second system time The end