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/19.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install gnome-gpg hostap-modules-2.6.8-4-386 rarpd shntool lesstif2 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: 0.92 0.98 0.91 2/55 30160 /proc/meminfo: memFree=278452/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=3152 CPUtime=0 /proc/30160/stat : 30160 (runsolver) R 30159 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28798531 3227648 32 18446744073709551615 134512640 134586868 4289907888 4289905936 4151690288 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.1166 s] /proc/loadavg: 0.92 0.98 0.91 2/55 30160 /proc/meminfo: memFree=278452/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=33244 CPUtime=0.13 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 1785 7207 0 0 6 1 4 2 20 0 1 0 28798531 34041856 1603 18446744073709551615 4194304 5184042 140737452095488 140737452092680 140215104059120 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 8311 1603 729 242 0 873 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 33244 [startup+0.200278 s] /proc/loadavg: 0.92 0.98 0.91 2/55 30160 /proc/meminfo: memFree=278452/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=35360 CPUtime=0.21 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 2315 7207 0 0 13 2 4 2 20 0 1 0 28798531 36208640 2132 18446744073709551615 4194304 5184042 140737452095488 140737452092680 140215103716916 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 8840 2132 729 242 0 1402 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35360 [startup+0.30026 s] /proc/loadavg: 0.92 0.98 0.91 2/55 30160 /proc/meminfo: memFree=278452/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=37852 CPUtime=0.31 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 3016 7207 0 0 21 4 4 2 20 0 1 0 28798531 38760448 2770 18446744073709551615 4194304 5184042 140737452095488 140737452092680 140215103779045 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 9463 2770 739 242 0 2025 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37852 [startup+0.700209 s] /proc/loadavg: 0.92 0.98 0.91 2/55 30160 /proc/meminfo: memFree=278452/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=64164 CPUtime=0.71 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 9713 7207 0 0 57 8 4 2 20 0 1 0 28798531 65703936 9394 18446744073709551615 4194304 5184042 140737452095488 140737452092920 4592300 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 16041 9394 851 242 0 8603 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 64164 [startup+1.5002 s] /proc/loadavg: 0.92 0.98 0.91 2/56 30180 /proc/meminfo: memFree=243484/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=64824 CPUtime=1.51 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 10049 7207 0 0 137 8 4 2 20 0 1 0 28798531 66379776 9601 18446744073709551615 4194304 5184042 140737452095488 140737452089784 140215103713659 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 16206 9601 851 242 0 8768 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 64824 [startup+3.10021 s] /proc/loadavg: 0.92 0.98 0.91 2/56 30180 /proc/meminfo: memFree=242740/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=66152 CPUtime=3.1 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 10551 7207 0 0 296 8 4 2 20 0 1 0 28798531 67739648 9846 18446744073709551615 4194304 5184042 140737452095488 140737452092792 140215120057879 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 16538 9846 851 242 0 9100 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 66152 [startup+6.30021 s] /proc/loadavg: 0.93 0.98 0.91 2/56 30180 /proc/meminfo: memFree=241252/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=68200 CPUtime=6.28 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 11459 7207 0 0 614 8 4 2 20 0 1 0 28798531 69836800 10241 18446744073709551615 4194304 5184042 140737452095488 140737452092936 140215120004200 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 17050 10241 851 242 0 9612 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 68200 [startup+12.7002 s] /proc/loadavg: 0.93 0.98 0.91 2/56 30180 /proc/meminfo: memFree=238028/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=72444 CPUtime=12.66 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 13283 7207 0 0 1251 9 4 2 20 0 1 0 28798531 74182656 11040 18446744073709551615 4194304 5184042 140737452095488 140737452092792 140215120042746 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 18111 11040 851 242 0 10673 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 72444 [startup+25.5002 s] /proc/loadavg: 0.95 0.98 0.91 2/56 30180 /proc/meminfo: memFree=230216/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=82000 CPUtime=25.4 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 17189 7207 0 0 2524 10 4 2 20 0 1 0 28798531 83968000 12897 18446744073709551615 4194304 5184042 140737452095488 140737452092792 140215103723765 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 20500 12897 851 242 0 13062 0 Current children cumulated CPU time (s) 25.4 Current children cumulated vsize (KiB) 82000 [startup+51.1002 s] /proc/loadavg: 0.96 0.98 0.91 2/56 30180 /proc/meminfo: memFree=199588/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=139924 CPUtime=50.9 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 37198 7207 0 0 5064 20 4 2 20 0 1 0 28798531 143282176 20616 18446744073709551615 4194304 5184042 140737452095488 140737452089784 140215120004534 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 34981 20616 851 242 0 27543 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 139924 [startup+102.3 s] /proc/loadavg: 0.98 0.98 0.91 2/56 30180 /proc/meminfo: memFree=152344/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=215336 CPUtime=101.89 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 65245 7207 0 0 10149 34 4 2 20 0 1 0 28798531 220504064 32278 18446744073709551615 4194304 5184042 140737452095488 140737452092920 140215120057896 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 53834 32278 851 242 0 46396 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 215336 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=123948/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=215336 CPUtime=161.64 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 72363 7207 0 0 16117 41 4 2 20 0 1 0 28798531 220504064 39396 18446744073709551615 4194304 5184042 140737452095488 140737452089752 140215112521418 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 53834 39396 851 242 0 46396 0 Current children cumulated CPU time (s) 161.64 Current children cumulated vsize (KiB) 215336 Solver just ended. Dumping a history of the last processes samples [startup+179.2 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=115764/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=178.47 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 74645 7207 0 0 17799 42 4 2 20 0 1 0 28798531 222027776 41678 18446744073709551615 4194304 5184042 140737452095488 140737452089736 140215120058092 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 41678 851 242 0 46768 0 Current children cumulated CPU time (s) 178.47 Current children cumulated vsize (KiB) 216824 [startup+192 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=112416/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=191.22 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 75177 7207 0 0 19073 43 4 2 20 0 1 0 28798531 222027776 42210 18446744073709551615 4194304 5184042 140737452095488 140737452089784 140215120057787 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 42210 851 242 0 46768 0 Current children cumulated CPU time (s) 191.22 Current children cumulated vsize (KiB) 216824 [startup+204.8 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=110184/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=203.97 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 75718 7207 0 0 20347 44 4 2 20 0 1 0 28798531 222027776 42751 18446744073709551615 4194304 5184042 140737452095488 140737452089704 140215120057888 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 42751 851 242 0 46768 0 Current children cumulated CPU time (s) 203.97 Current children cumulated vsize (KiB) 216824 [startup+211.2 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=109068/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=210.34 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 76008 7207 0 0 20984 44 4 2 20 0 1 0 28798531 222027776 43041 18446744073709551615 4194304 5184042 140737452095488 140737452089704 140215120058324 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 43041 851 242 0 46768 0 Current children cumulated CPU time (s) 210.34 Current children cumulated vsize (KiB) 216824 [startup+214.4 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=108696/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=213.52 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 76142 7207 0 0 21302 44 4 2 20 0 1 0 28798531 222027776 43175 18446744073709551615 4194304 5184042 140737452095488 140737452089704 140215120032157 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 43175 851 242 0 46768 0 Current children cumulated CPU time (s) 213.52 Current children cumulated vsize (KiB) 216824 [startup+215.2 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=108448/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=214.32 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 76167 7207 0 0 21382 44 4 2 20 0 1 0 28798531 222027776 43200 18446744073709551615 4194304 5184042 140737452095488 140737452089704 140215120057431 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 43200 851 242 0 46768 0 Current children cumulated CPU time (s) 214.32 Current children cumulated vsize (KiB) 216824 [startup+215.6 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=108324/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=214.72 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 76178 7207 0 0 21422 44 4 2 20 0 1 0 28798531 222027776 43211 18446744073709551615 4194304 5184042 140737452095488 140737452089784 140215104446191 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 43211 851 242 0 46768 0 Current children cumulated CPU time (s) 214.72 Current children cumulated vsize (KiB) 216824 [startup+215.8 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=108324/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=216824 CPUtime=214.92 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 76183 7207 0 0 21442 44 4 2 20 0 1 0 28798531 222027776 43216 18446744073709551615 4194304 5184042 140737452095488 140737452089752 140215120057948 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 54206 43216 851 242 0 46768 0 Current children cumulated CPU time (s) 214.92 Current children cumulated vsize (KiB) 216824 [startup+215.9 s] /proc/loadavg: 0.99 0.98 0.91 2/56 30180 /proc/meminfo: memFree=108324/1022884 swapFree=0/0 [pid=30160] ppid=30159 vsize=85728 CPUtime=215.02 /proc/30160/stat : 30160 (cupt) R 30159 30160 17872 34816 17872 4202496 76194 7207 0 0 21449 47 4 2 20 0 1 0 28798531 87785472 14835 18446744073709551615 4194304 5184042 140737452095488 140737452094648 140215103723565 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/30160/statm: 21432 14835 862 242 0 13994 0 Current children cumulated CPU time (s) 215.02 Current children cumulated vsize (KiB) 85728 Child status: 1 Real time (s): 215.977 CPU time (s): 215.117 CPU user time (s): 214.605 CPU system time (s): 0.512032 CPU usage (%): 99.6019 Max. virtual memory (cumulated for all children) (KiB): 216824 getrusage(RUSAGE_CHILDREN,...) data: user time used= 214.605 system time used= 0.512032 maximum resident set size= 188920 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 83421 page faults= 0 swaps= 0 block input operations= 0 block output operations= 8 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 3156 runsolver used 0.336021 second user time and 0.552034 second system time The end