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/136.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends remove gtkhtml3.2 slang1 secpolicy libnews-nntpclient-perl python2.3-numeric 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.81 0.41 2/55 24560 /proc/meminfo: memFree=282220/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=3152 CPUtime=0 /proc/24560/stat : 24560 (runsolver) R 24559 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28209387 3227648 33 18446744073709551615 134512640 134586868 4292334096 4292332144 4151522352 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.14522 s] /proc/loadavg: 0.99 0.81 0.41 2/55 24560 /proc/meminfo: memFree=282220/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=34036 CPUtime=0.16 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 1969 7204 0 0 8 1 5 2 20 0 1 0 28209387 34852864 1788 18446744073709551615 4194304 5184042 140735732804688 140735732801880 140516370460766 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 8509 1788 729 242 0 1071 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 34036 [startup+0.200278 s] /proc/loadavg: 0.99 0.81 0.41 2/55 24560 /proc/meminfo: memFree=282220/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=39844 CPUtime=0.22 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 3484 7204 0 0 13 2 5 2 20 0 1 0 28209387 40800256 3296 18446744073709551615 4194304 5184042 140735732804688 140735732800680 140516371115488 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 9961 3296 792 242 0 2523 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 39844 [startup+0.30028 s] /proc/loadavg: 0.99 0.81 0.41 2/55 24560 /proc/meminfo: memFree=282220/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=51320 CPUtime=0.32 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 6406 7204 0 0 22 3 5 2 20 0 1 0 28209387 52551680 6217 18446744073709551615 4194304 5184042 140735732804688 140735732801880 140516386755443 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 12830 6217 842 242 0 5392 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 51320 [startup+0.700179 s] /proc/loadavg: 0.99 0.81 0.41 2/55 24560 /proc/meminfo: memFree=282220/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=56600 CPUtime=0.72 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 7863 7204 0 0 62 3 5 2 20 0 1 0 28209387 57958400 7440 18446744073709551615 4194304 5184042 140735732804688 140735732801992 140516386748095 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 14150 7440 842 242 0 6712 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 56600 [startup+1.50019 s] /proc/loadavg: 0.99 0.81 0.41 2/56 24580 /proc/meminfo: memFree=254072/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=59044 CPUtime=1.52 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 8643 7204 0 0 142 3 5 2 20 0 1 0 28209387 60461056 7963 18446744073709551615 4194304 5184042 140735732804688 140735732798104 140516386714043 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 14761 7963 842 242 0 7323 0 Current children cumulated CPU time (s) 1.52 Current children cumulated vsize (KiB) 59044 [startup+3.10017 s] /proc/loadavg: 0.99 0.82 0.41 2/56 24580 /proc/meminfo: memFree=252088/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=62140 CPUtime=3.1 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 9754 7204 0 0 300 3 5 2 20 0 1 0 28209387 63631360 8561 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386714089 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 15535 8561 842 242 0 8097 0 Current children cumulated CPU time (s) 3.1 Current children cumulated vsize (KiB) 62140 [startup+6.30019 s] /proc/loadavg: 0.99 0.82 0.41 2/56 24580 /proc/meminfo: memFree=248616/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=66844 CPUtime=6.3 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 11481 7204 0 0 619 4 5 2 20 0 1 0 28209387 68448256 9263 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386739214 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 16711 9263 842 242 0 9273 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 66844 Solver just ended. Dumping a history of the last processes samples [startup+6.40028 s] /proc/loadavg: 0.99 0.82 0.41 2/56 24580 /proc/meminfo: memFree=248616/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=66844 CPUtime=6.4 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 11499 7204 0 0 629 4 5 2 20 0 1 0 28209387 68448256 9281 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386746770 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 16711 9281 842 242 0 9273 0 Current children cumulated CPU time (s) 6.4 Current children cumulated vsize (KiB) 66844 [startup+8.00018 s] /proc/loadavg: 0.99 0.82 0.42 2/56 24580 /proc/meminfo: memFree=247624/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=66844 CPUtime=7.98 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 11774 7204 0 0 787 4 5 2 20 0 1 0 28209387 68448256 9556 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386714023 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 16711 9556 842 242 0 9273 0 Current children cumulated CPU time (s) 7.98 Current children cumulated vsize (KiB) 66844 [startup+9.60018 s] /proc/loadavg: 0.99 0.82 0.42 2/56 24580 /proc/meminfo: memFree=246880/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=66844 CPUtime=9.57 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 12051 7204 0 0 946 4 5 2 20 0 1 0 28209387 68448256 9833 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386739202 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 16711 9833 842 242 0 9273 0 Current children cumulated CPU time (s) 9.57 Current children cumulated vsize (KiB) 66844 [startup+10.0032 s] /proc/loadavg: 0.99 0.82 0.42 2/56 24580 /proc/meminfo: memFree=246136/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=66844 CPUtime=9.97 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 12120 7204 0 0 986 4 5 2 20 0 1 0 28209387 68448256 9902 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386714023 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 16711 9902 842 242 0 9273 0 Current children cumulated CPU time (s) 9.97 Current children cumulated vsize (KiB) 66844 [startup+10.2002 s] /proc/loadavg: 0.99 0.82 0.42 2/56 24580 /proc/meminfo: memFree=246136/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=66844 CPUtime=10.18 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 12154 7204 0 0 1006 5 5 2 20 0 1 0 28209387 68448256 9936 18446744073709551615 4194304 5184042 140735732804688 140735732802120 140516386739227 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 16711 9936 842 242 0 9273 0 Current children cumulated CPU time (s) 10.18 Current children cumulated vsize (KiB) 66844 [startup+10.3002 s] /proc/loadavg: 0.99 0.82 0.42 2/56 24580 /proc/meminfo: memFree=246136/1022884 swapFree=0/0 [pid=24560] ppid=24559 vsize=58392 CPUtime=10.27 /proc/24560/stat : 24560 (cupt) R 24559 24560 17872 34816 17872 4202496 12175 7204 0 0 1015 5 5 2 20 0 1 0 28209387 59793408 8008 18446744073709551615 4194304 5184042 140735732804688 140735732804136 140516370386379 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/24560/statm: 14598 8008 853 242 0 7160 0 Current children cumulated CPU time (s) 10.27 Current children cumulated vsize (KiB) 58392 Child status: 1 Real time (s): 10.309 CPU time (s): 10.2966 CPU user time (s): 10.2126 CPU system time (s): 0.084005 CPU usage (%): 99.8805 Max. virtual memory (cumulated for all children) (KiB): 66844 getrusage(RUSAGE_CHILDREN,...) data: user time used= 10.2126 system time used= 0.084005 maximum resident set size= 40444 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 19399 page faults= 0 swaps= 0 block input operations= 0 block output operations= 24 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 170 runsolver used 0.048003 second user time and 0 second system time The end