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-sid/logs/17.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install libasedrive-usb rrdtool-tcl libapache-mod-auth-pgsql ttf-kochi-mincho libapache2-redirtoservname 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.99 0.98 0.98 2/55 2716 /proc/meminfo: memFree=539388/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=3152 CPUtime=0 /proc/2716/stat : 2716 (runsolver) R 2715 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29939241 3227648 33 18446744073709551615 134512640 134586868 4288349072 4288347120 4151432240 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.171299 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2716 /proc/meminfo: memFree=539388/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=34700 CPUtime=0.19 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 2148 7205 0 0 10 2 5 2 20 0 1 0 29939241 35532800 1965 18446744073709551615 4194304 5184042 140734876790800 140734876787992 140566855519796 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 8675 1965 729 242 0 1237 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 34700 [startup+0.200278 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2716 /proc/meminfo: memFree=539388/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=35360 CPUtime=0.22 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 2317 7205 0 0 13 2 5 2 20 0 1 0 29939241 36208640 2134 18446744073709551615 4194304 5184042 140734876790800 140734876787992 140566872046653 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 8840 2134 729 242 0 1402 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35360 [startup+0.30026 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2716 /proc/meminfo: memFree=539388/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=37852 CPUtime=0.32 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 3019 7205 0 0 22 3 5 2 20 0 1 0 29939241 38760448 2773 18446744073709551615 4194304 5184042 140734876790800 140734876787992 140566855450668 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 9463 2773 739 242 0 2025 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37852 [startup+0.700206 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2716 /proc/meminfo: memFree=539388/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=65440 CPUtime=0.72 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 10012 7205 0 0 56 9 5 2 20 0 1 0 29939241 67010560 9757 18446744073709551615 4194304 5184042 140734876790800 140734876788104 140566871625424 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 16360 9757 851 242 0 8922 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 65440 [startup+1.5002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=503048/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=66764 CPUtime=1.51 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 10478 7205 0 0 135 9 5 2 20 0 1 0 29939241 68366336 10029 18446744073709551615 4194304 5184042 140734876790800 140734876788104 140566871944412 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 16691 10029 851 242 0 9253 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 66764 [startup+3.10021 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=501684/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=69980 CPUtime=3.11 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 11638 7205 0 0 295 9 5 2 20 0 1 0 29939241 71659520 10419 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871860320 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 17495 10419 851 242 0 10057 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 69980 [startup+6.30021 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=499328/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=70840 CPUtime=6.3 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 12138 7205 0 0 613 10 5 2 20 0 1 0 29939241 72540160 10919 18446744073709551615 4194304 5184042 140734876790800 140734876788104 140566871944412 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 17710 10919 851 242 0 10272 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 70840 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=497344/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=75072 CPUtime=12.67 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 13620 7205 0 0 1249 11 5 2 20 0 1 0 29939241 76873728 11376 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871944456 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 18768 11376 851 242 0 11330 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 75072 [startup+25.5002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=493748/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=75340 CPUtime=25.41 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 14494 7205 0 0 2523 11 5 2 20 0 1 0 29939241 77148160 12250 18446744073709551615 4194304 5184042 140734876790800 140734876787624 140566871944466 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 18835 12250 851 242 0 11397 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 75340 [startup+51.1002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=487176/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=83532 CPUtime=50.91 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 18179 7205 0 0 5069 15 5 2 20 0 1 0 29939241 85536768 13886 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871944396 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 20883 13886 851 242 0 13445 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 83532 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=473784/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=100344 CPUtime=101.9 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 25583 7205 0 0 10165 18 5 2 20 0 1 0 29939241 102752256 17193 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871944456 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 25086 17193 851 242 0 17648 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 100344 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2736 /proc/meminfo: memFree=458656/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=133112 CPUtime=161.65 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 37559 7205 0 0 16130 28 5 2 20 0 1 0 29939241 136306688 20976 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871860643 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 33278 20976 851 242 0 25840 0 Current children cumulated CPU time (s) 161.65 Current children cumulated vsize (KiB) 133112 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2739 /proc/meminfo: memFree=441420/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=134932 CPUtime=221.4 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 41759 7205 0 0 22098 35 5 2 20 0 1 0 29939241 138170368 25176 18446744073709551615 4194304 5184042 140734876790800 140734876787624 140566855526552 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 33733 25176 851 242 0 26295 0 Current children cumulated CPU time (s) 221.4 Current children cumulated vsize (KiB) 134932 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2739 /proc/meminfo: memFree=426788/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=200468 CPUtime=281.17 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 61899 7205 0 0 28066 44 5 2 20 0 1 0 29939241 205279232 28931 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566855518661 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 50117 28931 851 242 0 42679 0 Current children cumulated CPU time (s) 281.17 Current children cumulated vsize (KiB) 200468 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2739 /proc/meminfo: memFree=422076/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=200468 CPUtime=298.79 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 63015 7205 0 0 29827 45 5 2 20 0 1 0 29939241 205279232 30047 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871872939 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 50117 30047 851 242 0 42679 0 Current children cumulated CPU time (s) 298.79 Current children cumulated vsize (KiB) 200468 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+300 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2739 /proc/meminfo: memFree=422076/1022884 swapFree=0/0 [pid=2716] ppid=2715 vsize=200468 CPUtime=298.79 /proc/2716/stat : 2716 (cupt) R 2715 2716 17872 34816 17872 4202496 63015 7205 0 0 29827 45 5 2 20 0 1 0 29939241 205279232 30047 18446744073709551615 4194304 5184042 140734876790800 140734876788232 140566871872939 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2716/statm: 50117 30047 851 242 0 42679 0 Current children cumulated CPU time (s) 298.79 Current children cumulated vsize (KiB) 200468 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.014 CPU time (s): 298.811 CPU user time (s): 298.331 CPU system time (s): 0.48003 CPU usage (%): 99.5991 Max. virtual memory (cumulated for all children) (KiB): 200468 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.331 system time used= 0.48003 maximum resident set size= 174144 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 70220 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 4357 runsolver used 0.444027 second user time and 0.780048 second system time The end