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/40.runsolver.aptitude aptitude -s -y --without-recommends install x-window-system-core libsub-uplevel-perl python2.2-docutils python-rpy mendexk 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.03 1.04 0.93 2/55 21423 /proc/meminfo: memFree=820696/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=3152 CPUtime=0 /proc/21423/stat : 21423 (runsolver) R 21422 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28405935 3227648 32 18446744073709551615 134512640 134586868 4291437488 4291435536 4152230960 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.202474 s] /proc/loadavg: 1.03 1.04 0.93 2/55 21423 /proc/meminfo: memFree=820696/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=89152 CPUtime=0.19 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 7871 1709 0 0 16 2 1 0 20 0 1 0 28405935 91291648 7662 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654073136 139882447721681 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 89152 [startup+0.300278 s] /proc/loadavg: 1.03 1.04 0.93 2/55 21423 /proc/meminfo: memFree=820696/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=101864 CPUtime=0.29 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 11710 1709 0 0 25 3 1 0 20 0 1 0 28405935 104308736 10756 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654072792 139882447773793 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 25466 10756 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 101864 [startup+0.400267 s] /proc/loadavg: 1.03 1.04 0.93 2/55 21423 /proc/meminfo: memFree=820696/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=101864 CPUtime=0.39 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 11710 1709 0 0 34 4 1 0 20 0 1 0 28405935 104308736 10756 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654072792 139882410060012 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 25466 10756 6746 1052 0 4036 0 Current children cumulated CPU time (s) 0.39 Current children cumulated vsize (KiB) 101864 [startup+0.700206 s] /proc/loadavg: 1.03 1.04 0.93 2/55 21423 /proc/meminfo: memFree=820696/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=114152 CPUtime=0.69 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 13715 1709 0 0 63 5 1 0 20 0 2 0 28405935 116891648 12087 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654074632 139882454509378 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 28538 12087 6977 1052 0 7108 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 114152 [startup+1.50024 s] /proc/loadavg: 1.03 1.04 0.93 2/57 21428 /proc/meminfo: memFree=799980/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=115572 CPUtime=1.49 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 14604 2209 0 0 140 8 1 0 20 0 2 0 28405935 118345728 12330 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654075384 139882410383737 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 28893 12330 7073 1052 0 7463 0 [pid=21423/tid=21428] ppid=21422 vsize=115572 CPUtime=0.01 /proc/21423/task/21428/stat : 21428 (aptitude) S 21422 21423 17863 34816 17863 4202560 6 2209 0 0 0 0 1 0 20 0 2 0 28405980 118345728 12330 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356279296 139882421617364 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 115572 [startup+3.10024 s] /proc/loadavg: 1.03 1.04 0.93 2/57 21429 /proc/meminfo: memFree=786092/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=142104 CPUtime=3.07 /proc/21423/stat : 21423 (aptitude) S 21422 21423 17863 34816 17863 4202496 22397 2209 0 0 296 10 1 0 20 0 2 0 28405935 145514496 19243 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654075120 139882421618251 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 35526 19243 7129 1052 0 14096 0 [pid=21423/tid=21428] ppid=21422 vsize=142104 CPUtime=1.14 /proc/21423/task/21428/stat : 21428 (aptitude) R 21422 21423 17863 34816 17863 4202560 7772 2209 0 0 111 2 1 0 20 0 2 0 28405980 145514496 19243 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356270744 139882410373392 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) 142104 [startup+6.30024 s] /proc/loadavg: 1.02 1.04 0.93 2/57 21429 /proc/meminfo: memFree=750132/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=168660 CPUtime=6.27 /proc/21423/stat : 21423 (aptitude) S 21422 21423 17863 34816 17863 4202496 29037 2209 0 0 614 12 1 0 20 0 2 0 28405935 172707840 25879 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654075120 139882421618251 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 42165 25879 7129 1052 0 20735 0 [pid=21423/tid=21428] ppid=21422 vsize=168660 CPUtime=4.33 /proc/21423/task/21428/stat : 21428 (aptitude) R 21422 21423 17863 34816 17863 4202560 14412 2209 0 0 428 4 1 0 20 0 2 0 28405980 172707840 25879 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356272776 139882455666145 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) 168660 Solver just ended. Dumping a history of the last processes samples [startup+6.50024 s] /proc/loadavg: 1.02 1.04 0.93 2/57 21429 /proc/meminfo: memFree=750132/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=170112 CPUtime=6.47 /proc/21423/stat : 21423 (aptitude) S 21422 21423 17863 34816 17863 4202496 29399 2209 0 0 634 12 1 0 20 0 2 0 28405935 174194688 26241 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654075120 139882421618251 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 42528 26241 7129 1052 0 21098 0 [pid=21423/tid=21428] ppid=21422 vsize=170112 CPUtime=4.53 /proc/21423/task/21428/stat : 21428 (aptitude) R 21422 21423 17863 34816 17863 4202560 14774 2209 0 0 448 4 1 0 20 0 2 0 28405980 174194688 26241 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356272824 139882410383712 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.47 Current children cumulated vsize (KiB) 170112 [startup+9.70024 s] /proc/loadavg: 1.02 1.04 0.93 2/57 21429 /proc/meminfo: memFree=722976/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=262500 CPUtime=9.65 /proc/21423/stat : 21423 (aptitude) S 21422 21423 17863 34816 17863 4202496 36146 2209 0 0 951 13 1 0 20 0 2 0 28405935 268800000 32970 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654075120 139882421618251 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 65625 32970 7129 1052 0 44195 0 [pid=21423/tid=21428] ppid=21422 vsize=262500 CPUtime=7.71 /proc/21423/task/21428/stat : 21428 (aptitude) R 21422 21423 17863 34816 17863 4202560 21520 2209 0 0 765 5 1 0 20 0 2 0 28405980 268800000 32970 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356272824 139882455675136 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.65 Current children cumulated vsize (KiB) 262500 [startup+11.3003 s] /proc/loadavg: 1.02 1.04 0.93 2/57 21429 /proc/meminfo: memFree=707600/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=273228 CPUtime=11.24 /proc/21423/stat : 21423 (aptitude) S 21422 21423 17863 34816 17863 4202496 38885 2209 0 0 1110 13 1 0 20 0 2 0 28405935 279785472 35629 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654075120 139882421618251 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 68307 35629 7129 1052 0 46877 0 [pid=21423/tid=21428] ppid=21422 vsize=273228 CPUtime=9.31 /proc/21423/task/21428/stat : 21428 (aptitude) R 21422 21423 17863 34816 17863 4202560 24259 2209 0 0 924 6 1 0 20 0 2 0 28405980 279785472 35629 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356272776 139882455581281 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 11.24 Current children cumulated vsize (KiB) 273228 [startup+12.1003 s] /proc/loadavg: 1.02 1.04 0.93 2/57 21429 /proc/meminfo: memFree=707600/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=277296 CPUtime=12.03 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 40277 2209 0 0 1188 14 1 0 20 0 2 0 28405935 283951104 36895 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654073496 139882410364593 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 69324 36895 7178 1052 0 47887 0 [pid=21423/tid=21428] ppid=21422 vsize=277296 CPUtime=9.9 /proc/21423/task/21428/stat : 21428 (aptitude) S 21422 21423 17863 34816 17863 4202560 25292 2209 0 0 983 6 1 0 20 0 2 0 28405980 283951104 36895 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356279296 139882421617364 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.03 Current children cumulated vsize (KiB) 277296 [startup+12.5011 s] /proc/loadavg: 1.02 1.04 0.93 2/57 21429 /proc/meminfo: memFree=701028/1022884 swapFree=0/0 [pid=21423] ppid=21422 vsize=277296 CPUtime=12.44 /proc/21423/stat : 21423 (aptitude) R 21422 21423 17863 34816 17863 4202496 42868 2709 0 0 1224 18 1 1 20 0 2 0 28405935 283951104 34797 18446744073709551615 139882452873216 139882457180568 140733654083360 140733654079624 139882410739178 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/21423/statm: 69324 34797 7179 1052 0 47887 0 [pid=21423/tid=21428] ppid=21422 vsize=277296 CPUtime=9.91 /proc/21423/task/21428/stat : 21428 (aptitude) S 21422 21423 17863 34816 17863 4202560 25292 2709 0 0 983 6 1 1 20 0 2 0 28405980 283951104 34797 18446744073709551615 139882452873216 139882457180568 140733654083360 139882356279296 139882421617364 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.44 Current children cumulated vsize (KiB) 277296 Child status: 0 Real time (s): 12.5373 CPU time (s): 12.4848 CPU user time (s): 12.2568 CPU system time (s): 0.228014 CPU usage (%): 99.5813 Max. virtual memory (cumulated for all children) (KiB): 277296 getrusage(RUSAGE_CHILDREN,...) data: user time used= 12.2568 system time used= 0.228014 maximum resident set size= 147912 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 45724 page faults= 0 swaps= 0 block input operations= 0 block output operations= 120 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 82 involuntary context switches= 262 runsolver used 0.024001 second user time and 0.040002 second system time The end