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/49.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install pathogen contact-lookup-applet libdbd-pg-perl exim gnusound 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.00 1.00 0.94 2/55 31065 /proc/meminfo: memFree=315580/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=3152 CPUtime=0 /proc/31065/stat : 31065 (runsolver) R 31064 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28998315 3227648 32 18446744073709551615 134512640 134586868 4289906672 4289904720 4151878704 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.164169 s] /proc/loadavg: 1.00 1.00 0.94 2/55 31065 /proc/meminfo: memFree=315580/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=34832 CPUtime=0.18 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 2172 7199 0 0 9 3 4 2 20 0 1 0 28998315 35667968 1989 18446744073709551615 4194304 5184042 140736004812464 140736004809656 139985161904320 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 8708 1989 729 242 0 1270 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 34832 [startup+0.200261 s] /proc/loadavg: 1.00 1.00 0.94 2/55 31065 /proc/meminfo: memFree=315580/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=35756 CPUtime=0.21 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 2399 7199 0 0 12 3 4 2 20 0 1 0 28998315 36614144 2216 18446744073709551615 4194304 5184042 140736004812464 140736004809656 139985161773379 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 8939 2216 729 242 0 1501 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35756 [startup+0.300245 s] /proc/loadavg: 1.00 1.00 0.94 2/55 31065 /proc/meminfo: memFree=315580/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=38796 CPUtime=0.31 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 3288 7199 0 0 21 4 4 2 20 0 1 0 28998315 39727104 3038 18446744073709551615 4194304 5184042 140736004812464 140736004808456 139985178844893 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 9699 3038 767 242 0 2261 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 38796 [startup+0.700182 s] /proc/loadavg: 1.00 1.00 0.94 2/55 31065 /proc/meminfo: memFree=315580/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=64836 CPUtime=0.72 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 9854 7199 0 0 58 8 4 2 20 0 1 0 28998315 66392064 9600 18446744073709551615 4194304 5184042 140736004812464 140736004809720 139985178183016 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 16209 9600 851 242 0 8771 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 64836 [startup+1.50021 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=279868/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=66924 CPUtime=1.51 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 10612 7199 0 0 137 8 4 2 20 0 1 0 28998315 68530176 9907 18446744073709551615 4194304 5184042 140736004812464 140736004809896 139985162491222 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 16731 9907 851 242 0 9293 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 66924 [startup+3.10021 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=278504/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=69116 CPUtime=3.1 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 11617 7199 0 0 295 9 4 2 20 0 1 0 28998315 70774784 10399 18446744073709551615 4194304 5184042 140736004812464 140736004809896 139985178163806 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 17279 10399 851 242 0 9841 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 69116 [startup+6.30021 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=275032/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=73212 CPUtime=6.29 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 13424 7199 0 0 612 11 4 2 20 0 1 0 28998315 74969088 11181 18446744073709551615 4194304 5184042 140736004812464 140736004809896 139985162491127 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 18303 11181 851 242 0 10865 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 73212 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=268584/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=81696 CPUtime=12.66 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 16999 7199 0 0 1248 12 4 2 20 0 1 0 28998315 83656704 12707 18446744073709551615 4194304 5184042 140736004812464 140736004806712 139985178212400 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 20424 12707 851 242 0 12986 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 81696 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=258416/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=98080 CPUtime=25.41 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 23533 7199 0 0 2519 16 4 2 20 0 1 0 28998315 100433920 15144 18446744073709551615 4194304 5184042 140736004812464 140736004806760 139985178129416 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 24520 15144 851 242 0 17082 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 98080 [startup+51.1002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=243164/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=131556 CPUtime=50.9 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 35524 7199 0 0 5062 22 4 2 20 0 1 0 28998315 134713344 18942 18446744073709551615 4194304 5184042 140736004812464 140736004809768 139985170251056 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 32889 18942 851 242 0 25451 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 131556 Solver just ended. Dumping a history of the last processes samples [startup+51.2003 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=243164/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=131556 CPUtime=51 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 35533 7199 0 0 5072 22 4 2 20 0 1 0 28998315 134713344 18951 18446744073709551615 4194304 5184042 140736004812464 140736004809768 139985178232144 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 32889 18951 851 242 0 25451 0 Current children cumulated CPU time (s) 51 Current children cumulated vsize (KiB) 131556 [startup+76.8002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=232500/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=131556 CPUtime=76.5 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 38221 7199 0 0 7620 24 4 2 20 0 1 0 28998315 134713344 21639 18446744073709551615 4194304 5184042 140736004812464 140736004809768 139985178182656 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 32889 21639 851 242 0 25451 0 Current children cumulated CPU time (s) 76.5 Current children cumulated vsize (KiB) 131556 [startup+83.2002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=226548/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=133268 CPUtime=82.87 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 39814 7199 0 0 8255 26 4 2 20 0 1 0 28998315 136466432 23232 18446744073709551615 4194304 5184042 140736004812464 140736004806680 139985170648043 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 33317 23232 851 242 0 25879 0 Current children cumulated CPU time (s) 82.87 Current children cumulated vsize (KiB) 133268 [startup+89.6002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=218364/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=134776 CPUtime=89.25 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 41734 7199 0 0 8891 28 4 2 20 0 1 0 28998315 138010624 25152 18446744073709551615 4194304 5184042 140736004812464 140736004806760 139985178183187 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 33694 25152 851 242 0 26256 0 Current children cumulated CPU time (s) 89.25 Current children cumulated vsize (KiB) 134776 [startup+92.8002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=207080/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=144036 CPUtime=92.43 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 44476 7199 0 0 9209 28 4 2 20 0 1 0 28998315 147492864 27894 18446744073709551615 4194304 5184042 140736004812464 140736004806760 139985178157479 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 36009 27894 851 242 0 28571 0 Current children cumulated CPU time (s) 92.43 Current children cumulated vsize (KiB) 144036 [startup+93.6031 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=206708/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=144036 CPUtime=93.23 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 44544 7199 0 0 9289 28 4 2 20 0 1 0 28998315 147492864 27962 18446744073709551615 4194304 5184042 140736004812464 140736004806760 139985178157483 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 36009 27962 851 242 0 28571 0 Current children cumulated CPU time (s) 93.23 Current children cumulated vsize (KiB) 144036 [startup+94.0002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=206708/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=144036 CPUtime=93.62 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 44581 7199 0 0 9328 28 4 2 20 0 1 0 28998315 147492864 27999 18446744073709551615 4194304 5184042 140736004812464 140736004806760 139985178183211 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 36009 27999 851 242 0 28571 0 Current children cumulated CPU time (s) 93.62 Current children cumulated vsize (KiB) 144036 [startup+94.2002 s] /proc/loadavg: 1.00 1.00 0.94 2/56 31085 /proc/meminfo: memFree=206708/1022884 swapFree=0/0 [pid=31065] ppid=31064 vsize=78496 CPUtime=93.83 /proc/31065/stat : 31065 (cupt) R 31064 31065 17872 34816 17872 4202496 44608 7199 0 0 9347 30 4 2 20 0 1 0 28998315 80379904 13039 18446744073709551615 4194304 5184042 140736004812464 140736004810840 139985161829970 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/31065/statm: 19624 13039 862 242 0 12186 0 Current children cumulated CPU time (s) 93.83 Current children cumulated vsize (KiB) 78496 Child status: 1 Real time (s): 94.276 CPU time (s): 93.9219 CPU user time (s): 93.5819 CPU system time (s): 0.340021 CPU usage (%): 99.6244 Max. virtual memory (cumulated for all children) (KiB): 144036 getrusage(RUSAGE_CHILDREN,...) data: user time used= 93.5818 system time used= 0.340021 maximum resident set size= 112104 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 51827 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= 1385 runsolver used 0.16001 second user time and 0.224014 second system time The end