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/logs/144.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove libvorbis0a kolourpaint libesd0 gedit dosfstools 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.93 2/55 29065 /proc/meminfo: memFree=303616/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=3152 CPUtime=0 /proc/29065/stat : 29065 (runsolver) R 29064 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28608385 3227648 32 18446744073709551615 134512640 134586868 4289463808 4289461856 4151383088 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.156471 s] /proc/loadavg: 1.00 1.00 0.93 2/55 29065 /proc/meminfo: memFree=303616/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=34304 CPUtime=0.17 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 2053 7197 0 0 10 1 4 2 20 0 1 0 28608385 35127296 1870 18446744073709551615 4194304 5184042 140734471592784 140734471589976 139956873204304 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 8576 1870 729 242 0 1138 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 34304 [startup+0.200263 s] /proc/loadavg: 1.00 1.00 0.93 2/55 29065 /proc/meminfo: memFree=303616/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=35360 CPUtime=0.21 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 2310 7197 0 0 13 2 4 2 20 0 1 0 28608385 36208640 2127 18446744073709551615 4194304 5184042 140734471592784 140734471589976 139956857086298 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 8840 2127 729 242 0 1402 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35360 [startup+0.300252 s] /proc/loadavg: 1.00 1.00 0.93 2/55 29065 /proc/meminfo: memFree=303616/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=46712 CPUtime=0.31 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 5265 7197 0 0 21 4 4 2 20 0 1 0 28608385 47833088 5074 18446744073709551615 4194304 5184042 140734471592784 140734471587272 139956874084191 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 11678 5074 835 242 0 4240 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 46712 [startup+0.700201 s] /proc/loadavg: 1.00 1.00 0.93 2/55 29065 /proc/meminfo: memFree=303616/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=58576 CPUtime=0.71 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 8258 7197 0 0 59 6 4 2 20 0 1 0 28608385 59981824 7969 18446744073709551615 4194304 5184042 140734471592784 140734471590216 139956865520704 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 14644 7969 842 242 0 7206 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 58576 [startup+1.5002 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=274352/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=59088 CPUtime=1.5 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 8533 7197 0 0 138 6 4 2 20 0 1 0 28608385 60506112 8115 18446744073709551615 4194304 5184042 140734471592784 140734471590216 139956873453787 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 14772 8115 842 242 0 7334 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 59088 [startup+3.10021 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=273732/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=60112 CPUtime=3.1 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 9068 7197 0 0 297 7 4 2 20 0 1 0 28608385 61554688 8393 18446744073709551615 4194304 5184042 140734471592784 140734471590232 139956857096655 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 15028 8393 842 242 0 7590 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 60112 [startup+6.3002 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=271500/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=69932 CPUtime=6.28 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 12074 7197 0 0 614 8 4 2 20 0 1 0 28608385 71610368 9861 18446744073709551615 4194304 5184042 140734471592784 140734471590088 139956857087805 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 17483 9861 842 242 0 10045 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 69932 [startup+12.7002 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=256372/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=77608 CPUtime=12.65 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 14884 7197 0 0 1248 11 4 2 20 0 1 0 28608385 79470592 12671 18446744073709551615 4194304 5184042 140734471592784 140734471587080 139956873452986 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 19402 12671 842 242 0 11964 0 Current children cumulated CPU time (s) 12.65 Current children cumulated vsize (KiB) 77608 [startup+25.5002 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=250420/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=85800 CPUtime=25.4 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 18375 7197 0 0 2522 12 4 2 20 0 1 0 28608385 87859200 14113 18446744073709551615 4194304 5184042 140734471592784 140734471587080 139956857086372 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 21450 14113 842 242 0 14012 0 Current children cumulated CPU time (s) 25.4 Current children cumulated vsize (KiB) 85800 [startup+51.1002 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=239012/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=102184 CPUtime=50.9 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 25324 7197 0 0 5067 17 4 2 20 0 1 0 28608385 104636416 16965 18446744073709551615 4194304 5184042 140734471592784 140734471590216 139956873192656 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 25546 16965 842 242 0 18108 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 102184 [startup+102.3 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=215700/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=134952 CPUtime=101.89 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 39293 7197 0 0 10159 24 4 2 20 0 1 0 28608385 138190848 22741 18446744073709551615 4194304 5184042 140734471592784 140734471587080 139956873431103 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 33738 22741 842 242 0 26300 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 134952 [startup+162.3 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=189412/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=200488 CPUtime=161.65 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 62255 7197 0 0 16124 35 4 2 20 0 1 0 28608385 205299712 29318 18446744073709551615 4194304 5184042 140734471592784 140734471590232 139956873430666 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 50122 29318 842 242 0 42684 0 Current children cumulated CPU time (s) 161.65 Current children cumulated vsize (KiB) 200488 [startup+222.303 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=162504/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=200488 CPUtime=221.4 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 68932 7197 0 0 22090 44 4 2 20 0 1 0 28608385 205299712 35995 18446744073709551615 4194304 5184042 140734471592784 140734471590232 139956873430422 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 50122 35995 842 242 0 42684 0 Current children cumulated CPU time (s) 221.4 Current children cumulated vsize (KiB) 200488 [startup+282.3 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=136216/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=200488 CPUtime=281.15 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 75570 7197 0 0 28056 53 4 2 20 0 1 0 28608385 205299712 42633 18446744073709551615 4194304 5184042 140734471592784 140734471587080 139956873377206 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 50122 42633 842 242 0 42684 0 Current children cumulated CPU time (s) 281.15 Current children cumulated vsize (KiB) 200488 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=137024/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=331560 CPUtime=298.77 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 110279 7197 0 0 29806 65 4 2 20 0 1 0 28608385 339517440 44573 18446744073709551615 4194304 5184042 140734471592784 140734471590216 139956873430112 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 82890 44573 842 242 0 75452 0 Current children cumulated CPU time (s) 298.77 Current children cumulated vsize (KiB) 331560 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: 1.00 1.00 0.93 2/56 29085 /proc/meminfo: memFree=137024/1022884 swapFree=0/0 [pid=29065] ppid=29064 vsize=331560 CPUtime=298.77 /proc/29065/stat : 29065 (cupt) R 29064 29065 17872 34816 17872 4202496 110279 7197 0 0 29806 65 4 2 20 0 1 0 28608385 339517440 44573 18446744073709551615 4194304 5184042 140734471592784 140734471590216 139956873430112 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29065/statm: 82890 44573 842 242 0 75452 0 Current children cumulated CPU time (s) 298.77 Current children cumulated vsize (KiB) 331560 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.016 CPU time (s): 298.807 CPU user time (s): 298.115 CPU system time (s): 0.692043 CPU usage (%): 99.597 Max. virtual memory (cumulated for all children) (KiB): 462636 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.115 system time used= 0.692043 maximum resident set size= 305168 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 117476 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= 4482 runsolver used 1.22808 second user time and 0 second system time The end