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/logs/60.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install eximon kid3 libwine-capi cpipe grcm 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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 0.96 0.47 0.18 2/55 22888 /proc/meminfo: memFree=284752/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=30148 CPUtime=0 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 774 0 0 0 0 0 0 0 20 0 1 0 28175465 30871552 673 18446744073709551615 4194304 5184042 140737053916912 140737053914920 140708671240638 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 7537 673 585 242 0 99 0 [startup+0.206269 s] /proc/loadavg: 0.96 0.47 0.18 2/55 22888 /proc/meminfo: memFree=284752/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=40504 CPUtime=0.22 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 3689 7202 0 0 13 3 5 1 20 0 1 0 28175465 41476096 3500 18446744073709551615 4194304 5184042 140737053916912 140737053913144 140708671423572 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 10126 3500 829 242 0 2688 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 40504 [startup+0.300271 s] /proc/loadavg: 0.96 0.47 0.18 2/55 22888 /proc/meminfo: memFree=284752/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=50488 CPUtime=0.31 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 6182 7202 0 0 21 4 5 1 20 0 1 0 28175465 51699712 5993 18446744073709551615 4194304 5184042 140737053916912 140737053910328 140708671987272 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 12622 5993 842 242 0 5184 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 50488 [startup+0.400276 s] /proc/loadavg: 0.96 0.47 0.18 2/55 22888 /proc/meminfo: memFree=284752/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=52784 CPUtime=0.41 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 6773 7202 0 0 31 4 5 1 20 0 1 0 28175465 54050816 6579 18446744073709551615 4194304 5184042 140737053916912 140737053911176 140708655433488 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 13196 6579 842 242 0 5758 0 Current children cumulated CPU time (s) 0.41 Current children cumulated vsize (KiB) 52784 [startup+0.700211 s] /proc/loadavg: 0.96 0.47 0.18 2/55 22888 /proc/meminfo: memFree=284752/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=58252 CPUtime=0.7 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 8265 7202 0 0 60 4 5 1 20 0 1 0 28175465 59650048 7877 18446744073709551615 4194304 5184042 140737053916912 140737053910280 140708671382626 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 14563 7877 842 242 0 7125 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 58252 [startup+1.50021 s] /proc/loadavg: 0.96 0.48 0.18 2/56 22908 /proc/meminfo: memFree=255240/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=60136 CPUtime=1.5 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 9022 7202 0 0 140 4 5 1 20 0 1 0 28175465 61579264 8377 18446744073709551615 4194304 5184042 140737053916912 140737053911208 140708655038988 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 15034 8377 842 242 0 7596 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 60136 [startup+3.1002 s] /proc/loadavg: 0.96 0.48 0.18 2/56 22908 /proc/meminfo: memFree=253752/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=63100 CPUtime=3.1 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 10074 7202 0 0 299 5 5 1 20 0 1 0 28175465 64614400 8916 18446744073709551615 4194304 5184042 140737053916912 140737053914216 140708671391423 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 15775 8916 842 242 0 8337 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 63100 [startup+6.30021 s] /proc/loadavg: 0.96 0.48 0.18 2/56 22908 /proc/meminfo: memFree=250528/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=67648 CPUtime=6.29 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 11787 7202 0 0 616 7 5 1 20 0 1 0 28175465 69271552 9604 18446744073709551615 4194304 5184042 140737053916912 140737053914216 140708671390109 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 16912 9604 842 242 0 9474 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 67648 Solver just ended. Dumping a history of the last processes samples [startup+6.5002 s] /proc/loadavg: 0.96 0.48 0.18 2/56 22908 /proc/meminfo: memFree=250528/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=67648 CPUtime=6.49 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 11825 7202 0 0 636 7 5 1 20 0 1 0 28175465 69271552 9642 18446744073709551615 4194304 5184042 140737053916912 140737053914216 4592305 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 16912 9642 842 242 0 9474 0 Current children cumulated CPU time (s) 6.49 Current children cumulated vsize (KiB) 67648 [startup+8.10022 s] /proc/loadavg: 0.96 0.49 0.19 2/56 22908 /proc/meminfo: memFree=247304/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=69032 CPUtime=8.07 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 12437 7202 0 0 794 7 5 1 20 0 1 0 28175465 70688768 10254 18446744073709551615 4194304 5184042 140737053916912 140737053914216 140708671382528 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 17258 10254 842 242 0 9820 0 Current children cumulated CPU time (s) 8.07 Current children cumulated vsize (KiB) 69032 [startup+9.7002 s] /proc/loadavg: 0.96 0.49 0.19 2/56 22908 /proc/meminfo: memFree=246560/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=69032 CPUtime=9.67 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 12699 7202 0 0 953 8 5 1 20 0 1 0 28175465 70688768 10516 18446744073709551615 4194304 5184042 140737053916912 140737053914216 140708671153376 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 17258 10516 842 242 0 9820 0 Current children cumulated CPU time (s) 9.67 Current children cumulated vsize (KiB) 69032 [startup+10.1074 s] /proc/loadavg: 0.96 0.49 0.19 2/56 22908 /proc/meminfo: memFree=245816/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=69032 CPUtime=10.08 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 12764 7202 0 0 994 8 5 1 20 0 1 0 28175465 70688768 10581 18446744073709551615 4194304 5184042 140737053916912 140737053914216 140708671383268 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 17258 10581 842 242 0 9820 0 Current children cumulated CPU time (s) 10.08 Current children cumulated vsize (KiB) 69032 [startup+10.5002 s] /proc/loadavg: 0.96 0.49 0.19 2/56 22908 /proc/meminfo: memFree=245816/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=69032 CPUtime=10.46 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 12828 7202 0 0 1032 8 5 1 20 0 1 0 28175465 70688768 10645 18446744073709551615 4194304 5184042 140737053916912 140737053914216 140708671357979 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 17258 10645 842 242 0 9820 0 Current children cumulated CPU time (s) 10.46 Current children cumulated vsize (KiB) 69032 [startup+10.6002 s] /proc/loadavg: 0.96 0.49 0.19 2/56 22908 /proc/meminfo: memFree=245816/1022884 swapFree=0/0 [pid=22888] ppid=22887 vsize=60580 CPUtime=10.57 /proc/22888/stat : 22888 (cupt) R 22887 22888 17872 34816 17872 4202496 14898 7202 0 0 1042 9 5 1 20 0 1 0 28175465 62033920 8548 18446744073709551615 4194304 5184042 140737053916912 140737053916360 140708672027791 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/22888/statm: 15145 8548 853 242 0 7707 0 Current children cumulated CPU time (s) 10.57 Current children cumulated vsize (KiB) 60580 Child status: 1 Real time (s): 10.6189 CPU time (s): 10.6047 CPU user time (s): 10.4967 CPU system time (s): 0.108006 CPU usage (%): 99.8664 Max. virtual memory (cumulated for all children) (KiB): 69032 getrusage(RUSAGE_CHILDREN,...) data: user time used= 10.4967 system time used= 0.108006 maximum resident set size= 50796 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22120 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= 180 runsolver used 0.032002 second user time and 0.020001 second system time The end