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-squeeze/logs/59.runsolver.aptitude aptitude -s -y --without-recommends install bonobo-conf gdis ooo2dbk python-optik libmon-perl 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.02 1.06 1.01 2/55 23658 /proc/meminfo: memFree=869816/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=3152 CPUtime=0 /proc/23658/stat : 23658 (runsolver) R 23657 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28972931 3227648 32 18446744073709551615 134512640 134586868 4289637520 4289635568 4151739440 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.149977 s] /proc/loadavg: 1.02 1.06 1.01 2/55 23658 /proc/meminfo: memFree=869816/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=100508 CPUtime=0.13 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 10598 1709 0 0 10 3 0 0 20 0 1 0 28972931 102920192 10400 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137424 139923641376836 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 25127 10400 9225 1052 0 1122 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 100508 [startup+0.200272 s] /proc/loadavg: 1.02 1.06 1.01 2/55 23658 /proc/meminfo: memFree=869816/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=100508 CPUtime=0.18 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 10606 1709 0 0 15 3 0 0 20 0 1 0 28972931 102920192 10408 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137424 139923640817124 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 25127 10408 9233 1052 0 1122 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 100508 [startup+0.300264 s] /proc/loadavg: 1.02 1.06 1.01 2/55 23658 /proc/meminfo: memFree=869816/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=111108 CPUtime=0.28 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 13341 1709 0 0 25 3 0 0 20 0 1 0 28972931 113774592 13135 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137272 139923640829922 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 27777 13135 9303 1052 0 3772 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 111108 [startup+0.700176 s] /proc/loadavg: 1.02 1.06 1.01 2/55 23658 /proc/meminfo: memFree=869816/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=123288 CPUtime=0.69 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 17028 1709 0 0 63 6 0 0 20 0 2 0 28972931 126246912 14303 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393141944 139923641376456 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 30822 14303 9482 1052 0 6817 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 123288 [startup+1.50022 s] /proc/loadavg: 1.02 1.06 1.01 2/57 23663 /proc/meminfo: memFree=841536/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=132524 CPUtime=1.48 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 19456 1709 0 0 142 6 0 0 20 0 2 0 28972931 135704576 16726 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393133320 139923614712096 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 33131 16726 9585 1052 0 9126 0 [pid=23658/tid=23663] ppid=23657 vsize=132524 CPUtime=0 /proc/23658/task/23663/stat : 23663 (aptitude) S 23657 23658 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 28972991 135704576 16726 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536803840 139923614720724 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) 132524 [startup+3.10024 s] /proc/loadavg: 1.02 1.06 1.01 2/57 23664 /proc/meminfo: memFree=840048/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=138296 CPUtime=3.08 /proc/23658/stat : 23658 (aptitude) S 23657 23658 17863 34816 17863 4202496 22003 2207 0 0 297 10 0 1 20 0 2 0 28972931 141615104 18302 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137920 139923614721611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 34574 18302 9697 1052 0 10569 0 [pid=23658/tid=23663] ppid=23657 vsize=138296 CPUtime=0.16 /proc/23658/task/23663/stat : 23663 (aptitude) R 23657 23658 17863 34816 17863 4202560 1406 2207 0 0 15 0 0 1 20 0 2 0 28972991 141615104 18302 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536794232 139923648684641 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 138296 [startup+6.30024 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=799376/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=185028 CPUtime=6.27 /proc/23658/stat : 23658 (aptitude) S 23657 23658 17863 34816 17863 4202496 34130 2207 0 0 608 18 0 1 20 0 2 0 28972931 189468672 29966 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137920 139923614721611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 46257 29966 9700 1052 0 22252 0 [pid=23658/tid=23663] ppid=23657 vsize=185028 CPUtime=3.35 /proc/23658/task/23663/stat : 23663 (aptitude) R 23657 23658 17863 34816 17863 4202560 13532 2207 0 0 326 8 0 1 20 0 2 0 28972991 189468672 29966 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536797416 139923648538684 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 185028 [startup+12.7002 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=755852/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=285280 CPUtime=12.63 /proc/23658/stat : 23658 (aptitude) S 23657 23658 17863 34816 17863 4202496 43134 2207 0 0 1242 20 0 1 20 0 2 0 28972931 292126720 38643 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137920 139923614721611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 71320 38643 9700 1052 0 47315 0 [pid=23658/tid=23663] ppid=23657 vsize=285280 CPUtime=9.71 /proc/23658/task/23663/stat : 23663 (aptitude) R 23657 23658 17863 34816 17863 4202560 22535 2207 0 0 960 10 0 1 20 0 2 0 28972991 292126720 38643 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536795160 139923611889152 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) 285280 Solver just ended. Dumping a history of the last processes samples [startup+12.8003 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=755852/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=285940 CPUtime=12.73 /proc/23658/stat : 23658 (aptitude) S 23657 23658 17863 34816 17863 4202496 43321 2207 0 0 1252 20 0 1 20 0 2 0 28972931 292802560 38830 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137920 139923614721611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 71485 38830 9700 1052 0 47480 0 [pid=23658/tid=23663] ppid=23657 vsize=285940 CPUtime=9.81 /proc/23658/task/23663/stat : 23663 (aptitude) R 23657 23658 17863 34816 17863 4202560 22722 2207 0 0 970 10 0 1 20 0 2 0 28972991 292802560 38830 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536795112 139923648606864 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.73 Current children cumulated vsize (KiB) 285940 [startup+16.0002 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=736136/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=308128 CPUtime=15.92 /proc/23658/stat : 23658 (aptitude) S 23657 23658 17863 34816 17863 4202496 48876 2207 0 0 1569 22 0 1 20 0 2 0 28972931 315523072 44341 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137920 139923614721611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 77032 44341 9700 1052 0 53027 0 [pid=23658/tid=23663] ppid=23657 vsize=308128 CPUtime=13 /proc/23658/task/23663/stat : 23663 (aptitude) R 23657 23658 17863 34816 17863 4202560 28277 2207 0 0 1287 12 0 1 20 0 2 0 28972991 315523072 44341 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536795112 139923603476819 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 15.92 Current children cumulated vsize (KiB) 308128 [startup+17.6002 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=718032/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=320668 CPUtime=17.51 /proc/23658/stat : 23658 (aptitude) S 23657 23658 17863 34816 17863 4202496 52038 2207 0 0 1725 25 0 1 20 0 2 0 28972931 328364032 47474 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393137920 139923614721611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 80167 47474 9700 1052 0 56162 0 [pid=23658/tid=23663] ppid=23657 vsize=320668 CPUtime=14.6 /proc/23658/task/23663/stat : 23663 (aptitude) R 23657 23658 17863 34816 17863 4202560 31439 2207 0 0 1444 15 0 1 20 0 2 0 28972991 328364032 47474 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536795160 139923648622874 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 17.51 Current children cumulated vsize (KiB) 320668 [startup+18.4002 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=718032/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=322444 CPUtime=18.31 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 55182 2207 0 0 1804 26 0 1 20 0 2 0 28972931 330182656 48053 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393138360 139923648182951 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 80611 48053 9749 1052 0 56599 0 [pid=23658/tid=23663] ppid=23657 vsize=322444 CPUtime=14.85 /proc/23658/task/23663/stat : 23663 (aptitude) S 23657 23658 17863 34816 17863 4202560 31889 2207 0 0 1469 15 0 1 20 0 2 0 28972991 330182656 48053 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536803840 139923614720724 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 18.31 Current children cumulated vsize (KiB) 322444 [startup+18.6002 s] /proc/loadavg: 1.02 1.05 1.01 2/57 23664 /proc/meminfo: memFree=718032/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=322444 CPUtime=18.51 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 55496 2707 0 0 1817 32 0 2 20 0 2 0 28972931 330182656 48234 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393136872 139923603820613 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 80611 48234 9749 1052 0 56599 0 [pid=23658/tid=23663] ppid=23657 vsize=322444 CPUtime=14.86 /proc/23658/task/23663/stat : 23663 (aptitude) S 23657 23658 17863 34816 17863 4202560 31889 2707 0 0 1469 15 0 2 20 0 2 0 28972991 330182656 48234 18446744073709551615 139923645976576 139923650283928 140737393146160 139923536803840 139923614720724 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 18.51 Current children cumulated vsize (KiB) 322444 [startup+18.701 s] /proc/loadavg: 1.02 1.05 1.01 2/56 23665 /proc/meminfo: memFree=777552/1022884 swapFree=0/0 [pid=23658] ppid=23657 vsize=293048 CPUtime=18.61 /proc/23658/stat : 23658 (aptitude) R 23657 23658 17863 34816 17863 4202496 55989 2707 0 0 1822 37 0 2 20 0 1 0 28972931 300081152 32541 18446744073709551615 139923645976576 139923650283928 140737393146160 140737393143208 139923603842538 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/23658/statm: 73262 32541 9752 1052 0 49250 0 Current children cumulated CPU time (s) 18.61 Current children cumulated vsize (KiB) 293048 Child status: 0 Real time (s): 18.7366 CPU time (s): 18.6572 CPU user time (s): 18.2331 CPU system time (s): 0.424026 CPU usage (%): 99.5759 Max. virtual memory (cumulated for all children) (KiB): 322444 getrusage(RUSAGE_CHILDREN,...) data: user time used= 18.2331 system time used= 0.424026 maximum resident set size= 193156 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 58806 page faults= 0 swaps= 0 block input operations= 0 block output operations= 144 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 92 involuntary context switches= 363 runsolver used 0.032002 second user time and 0.060003 second system time The end