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/148.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove kdeartwork-theme-icon menu pkg-config epiphany-browser klettres-data 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 0.99 0.99 2/55 8244 /proc/meminfo: memFree=572228/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=3152 CPUtime=0 /proc/8244/stat : 8244 (runsolver) R 8243 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 31847306 3227648 32 18446744073709551615 134512640 134586868 4288320144 4288318192 4151989296 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.165964 s] /proc/loadavg: 1.00 0.99 0.99 2/55 8244 /proc/meminfo: memFree=572228/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=34700 CPUtime=0.18 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 2134 7194 0 0 10 2 4 2 20 0 1 0 31847306 35532800 1951 18446744073709551615 4194304 5184042 140735680339424 140735680336616 139794789365488 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 8675 1951 729 242 0 1237 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 34700 [startup+0.200275 s] /proc/loadavg: 1.00 0.99 0.99 2/55 8244 /proc/meminfo: memFree=572228/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=35492 CPUtime=0.21 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 2339 7194 0 0 12 3 4 2 20 0 1 0 31847306 36343808 2156 18446744073709551615 4194304 5184042 140735680339424 140735680336616 139794789023284 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 8873 2156 729 242 0 1435 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35492 [startup+0.300258 s] /proc/loadavg: 1.00 0.99 0.99 2/55 8244 /proc/meminfo: memFree=572228/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=37984 CPUtime=0.31 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 3044 7194 0 0 20 5 4 2 20 0 1 0 31847306 38895616 2798 18446744073709551615 4194304 5184042 140735680339424 140735680336616 139794806228847 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 9496 2798 739 242 0 2058 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 37984 [startup+0.700202 s] /proc/loadavg: 1.00 0.99 0.99 2/55 8244 /proc/meminfo: memFree=572228/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=63928 CPUtime=0.71 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 9651 7194 0 0 54 11 4 2 20 0 1 0 31847306 65462272 9396 18446744073709551615 4194304 5184042 140735680339424 140735680336632 139794805363712 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 15982 9396 851 242 0 8544 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 63928 [startup+1.50021 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=535276/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=68540 CPUtime=1.51 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 11060 7194 0 0 133 12 4 2 20 0 1 0 31847306 70184960 10354 18446744073709551615 4194304 5184042 140735680339424 140735680336728 139794805364136 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 17135 10354 851 242 0 9697 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 68540 [startup+3.10021 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=532548/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=71752 CPUtime=3.1 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 12495 7194 0 0 292 12 4 2 20 0 1 0 31847306 73474048 11276 18446744073709551615 4194304 5184042 140735680339424 140735680336728 139794789020815 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 17938 11276 851 242 0 10500 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 71752 [startup+6.3002 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=523496/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=80236 CPUtime=6.28 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 15366 7194 0 0 608 14 4 2 20 0 1 0 31847306 82161664 13122 18446744073709551615 4194304 5184042 140735680339424 140735680333720 139794805364128 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 20059 13122 851 242 0 12621 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 80236 [startup+12.7002 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=514320/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=104964 CPUtime=12.66 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 23983 7194 0 0 1241 19 4 2 20 0 1 0 31847306 107483136 15593 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805363808 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 26241 15593 851 242 0 18803 0 Current children cumulated CPU time (s) 12.66 Current children cumulated vsize (KiB) 104964 [startup+25.5002 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=487164/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=137732 CPUtime=25.4 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 38779 7194 0 0 2508 26 4 2 20 0 1 0 31847306 141037568 22196 18446744073709551615 4194304 5184042 140735680339424 140735680336872 139794805344862 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 34433 22196 851 242 0 26995 0 Current children cumulated CPU time (s) 25.4 Current children cumulated vsize (KiB) 137732 [startup+51.1003 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=427396/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=203268 CPUtime=50.91 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 70261 7194 0 0 5041 44 4 2 20 0 1 0 31847306 208146432 37293 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805363696 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 50817 37293 851 242 0 43379 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 203268 [startup+102.3 s] /proc/loadavg: 1.00 0.99 0.99 2/56 8264 /proc/meminfo: memFree=312572/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=334340 CPUtime=101.91 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 131362 7194 0 0 10113 72 4 2 20 0 1 0 31847306 342364160 65625 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794789010967 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 83585 65625 851 242 0 76147 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 334340 [startup+162.3 s] /proc/loadavg: 1.04 1.00 0.99 2/56 8264 /proc/meminfo: memFree=214056/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=161.65 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 223492 7194 0 0 16041 118 4 2 20 0 1 0 31847306 610799616 92218 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805364123 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 92218 851 242 0 141683 0 Current children cumulated CPU time (s) 161.65 Current children cumulated vsize (KiB) 596484 [startup+222.303 s] /proc/loadavg: 1.01 1.00 0.99 2/56 8264 /proc/meminfo: memFree=106920/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=221.42 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 250141 7194 0 0 22000 136 4 2 20 0 1 0 31847306 610799616 118867 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794789015323 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 118867 851 242 0 141683 0 Current children cumulated CPU time (s) 221.42 Current children cumulated vsize (KiB) 596484 Solver just ended. Dumping a history of the last processes samples [startup+230.4 s] /proc/loadavg: 1.01 1.00 0.99 2/56 8264 /proc/meminfo: memFree=93032/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=229.48 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 253747 7194 0 0 22803 139 4 2 20 0 1 0 31847306 610799616 122473 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794789029911 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 122473 851 242 0 141683 0 Current children cumulated CPU time (s) 229.48 Current children cumulated vsize (KiB) 596484 [startup+256 s] /proc/loadavg: 1.01 1.00 0.99 2/56 8264 /proc/meminfo: memFree=47276/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=254.99 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 265294 7194 0 0 25345 148 4 2 20 0 1 0 31847306 610799616 134020 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805537632 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 134020 851 242 0 141683 0 Current children cumulated CPU time (s) 254.99 Current children cumulated vsize (KiB) 596484 [startup+268.8 s] /proc/loadavg: 1.00 1.00 0.99 2/56 8264 /proc/meminfo: memFree=23840/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=267.73 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 270990 7194 0 0 26616 151 4 2 20 0 1 0 31847306 610799616 139716 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794789020652 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 139716 851 242 0 141683 0 Current children cumulated CPU time (s) 267.73 Current children cumulated vsize (KiB) 596484 [startup+272 s] /proc/loadavg: 1.00 1.00 0.99 2/56 8264 /proc/meminfo: memFree=18136/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=270.91 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 272313 7194 0 0 26933 152 4 2 20 0 1 0 31847306 610799616 141039 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805338535 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 141039 851 242 0 141683 0 Current children cumulated CPU time (s) 270.91 Current children cumulated vsize (KiB) 596484 [startup+273.6 s] /proc/loadavg: 1.00 1.00 0.99 2/56 8264 /proc/meminfo: memFree=16400/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=272.52 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 273087 7194 0 0 27092 154 4 2 20 0 1 0 31847306 610799616 141813 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805364535 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 141813 851 242 0 141683 0 Current children cumulated CPU time (s) 272.52 Current children cumulated vsize (KiB) 596484 [startup+274.4 s] /proc/loadavg: 1.00 1.00 0.99 2/56 8264 /proc/meminfo: memFree=14292/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=273.3 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 273362 7194 0 0 27170 154 4 2 20 0 1 0 31847306 610799616 142088 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805413200 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 142088 851 242 0 141683 0 Current children cumulated CPU time (s) 273.3 Current children cumulated vsize (KiB) 596484 [startup+275.2 s] /proc/loadavg: 1.00 1.00 0.99 2/56 8264 /proc/meminfo: memFree=12680/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=274.11 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 273670 7194 0 0 27250 155 4 2 20 0 1 0 31847306 610799616 142396 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805379919 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 142396 851 242 0 141683 0 Current children cumulated CPU time (s) 274.11 Current children cumulated vsize (KiB) 596484 [startup+275.4 s] /proc/loadavg: 1.00 1.00 0.99 2/56 8264 /proc/meminfo: memFree=12680/1022884 swapFree=0/0 [pid=8244] ppid=8243 vsize=596484 CPUtime=274.31 /proc/8244/stat : 8244 (cupt) R 8243 8244 17872 34816 17872 4202496 273784 7194 0 0 27270 155 4 2 20 0 1 0 31847306 610799616 142510 18446744073709551615 4194304 5184042 140735680339424 140735680336856 139794805364194 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/8244/statm: 149121 142510 851 242 0 141683 0 Current children cumulated CPU time (s) 274.31 Current children cumulated vsize (KiB) 596484 Child ended because it received signal 6 (SIGABRT) Real time (s): 275.5 CPU time (s): 274.385 CPU user time (s): 272.773 CPU system time (s): 1.6121 CPU usage (%): 99.5955 Max. virtual memory (cumulated for all children) (KiB): 858632 getrusage(RUSAGE_CHILDREN,...) data: user time used= 272.773 system time used= 1.6121 maximum resident set size= 570188 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 281013 page faults= 3 swaps= 0 block input operations= 432 block output operations= 8 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 55 involuntary context switches= 4041 runsolver used 0.316019 second user time and 0.780048 second system time The end