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/logs/2.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install libgcj4-dev cacti gnubg kronolith ppp 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.78 0.92 0.90 2/55 29553 /proc/meminfo: memFree=279444/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=3152 CPUtime=0 /proc/29553/stat : 29553 (runsolver) R 29552 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28679683 3227648 32 18446744073709551615 134512640 134586868 4288724544 4288722592 4151260208 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.167447 s] /proc/loadavg: 0.78 0.92 0.90 2/55 29553 /proc/meminfo: memFree=279444/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=34700 CPUtime=0.18 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 2127 7195 0 0 8 3 5 2 20 0 1 0 28679683 35532800 1945 18446744073709551615 4194304 5184042 140735862751120 140735862748312 139852688498183 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 8675 1945 729 242 0 1237 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 34700 [startup+0.20027 s] /proc/loadavg: 0.78 0.92 0.90 2/55 29553 /proc/meminfo: memFree=279444/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=35360 CPUtime=0.21 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 2321 7195 0 0 10 4 5 2 20 0 1 0 28679683 36208640 2139 18446744073709551615 4194304 5184042 140735862751120 140735862748312 139852688498183 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 8840 2139 729 242 0 1402 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 35360 [startup+0.300255 s] /proc/loadavg: 0.78 0.92 0.90 2/55 29553 /proc/meminfo: memFree=279444/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=37984 CPUtime=0.32 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 3029 7195 0 0 20 5 5 2 20 0 1 0 28679683 38895616 2784 18446744073709551615 4194304 5184042 140735862751120 140735862748312 139852688461364 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 9496 2784 739 242 0 2058 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37984 [startup+0.700207 s] /proc/loadavg: 0.78 0.92 0.90 2/55 29553 /proc/meminfo: memFree=279444/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=66876 CPUtime=0.72 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 10359 7195 0 0 55 10 5 2 20 0 1 0 28679683 68481024 10106 18446744073709551615 4194304 5184042 140735862751120 140735862748376 139852705467045 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 16719 10106 851 242 0 9281 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 66876 [startup+1.50021 s] /proc/loadavg: 0.78 0.92 0.90 2/56 29573 /proc/meminfo: memFree=241996/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=67644 CPUtime=1.52 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 10687 7195 0 0 135 10 5 2 20 0 1 0 28679683 69267456 10240 18446744073709551615 4194304 5184042 140735862751120 140735862748552 139852704801783 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 16911 10240 851 242 0 9473 0 Current children cumulated CPU time (s) 1.52 Current children cumulated vsize (KiB) 67644 [startup+3.10021 s] /proc/loadavg: 0.78 0.92 0.90 2/56 29573 /proc/meminfo: memFree=241004/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=68816 CPUtime=3.11 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 11203 7195 0 0 294 10 5 2 20 0 1 0 28679683 70467584 10499 18446744073709551615 4194304 5184042 140735862751120 140735862748424 139852704802308 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 17204 10499 851 242 0 9766 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 68816 [startup+6.30019 s] /proc/loadavg: 0.80 0.92 0.90 2/56 29573 /proc/meminfo: memFree=239144/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=71000 CPUtime=6.3 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 12256 7195 0 0 612 11 5 2 20 0 1 0 28679683 72704000 11039 18446744073709551615 4194304 5184042 140735862751120 140735862748424 139852704776643 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 17750 11039 851 242 0 10312 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 71000 [startup+12.7002 s] /proc/loadavg: 0.81 0.93 0.90 2/56 29573 /proc/meminfo: memFree=234432/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=75648 CPUtime=12.67 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 14430 7195 0 0 1248 12 5 2 20 0 1 0 28679683 77463552 12188 18446744073709551615 4194304 5184042 140735862751120 140735862748424 139852704802537 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 18912 12188 851 242 0 11474 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 75648 [startup+25.5002 s] /proc/loadavg: 0.85 0.93 0.90 2/56 29573 /proc/meminfo: memFree=225256/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=84572 CPUtime=25.41 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 18684 7195 0 0 2521 13 5 2 20 0 1 0 28679683 86601728 14393 18446744073709551615 4194304 5184042 140735862751120 140735862748424 139852688449195 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 21143 14393 851 242 0 13705 0 Current children cumulated CPU time (s) 25.41 Current children cumulated vsize (KiB) 84572 [startup+51.1002 s] /proc/loadavg: 0.90 0.93 0.90 2/56 29573 /proc/meminfo: memFree=202936/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=110856 CPUtime=50.91 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 28317 7195 0 0 5064 20 5 2 20 0 1 0 28679683 113516544 19929 18446744073709551615 4194304 5184042 140735862751120 140735862745368 139852696883712 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 27714 19929 851 242 0 20276 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 110856 Solver just ended. Dumping a history of the last processes samples [startup+51.2003 s] /proc/loadavg: 0.90 0.93 0.90 2/56 29573 /proc/meminfo: memFree=202936/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=110856 CPUtime=51 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 28324 7195 0 0 5073 20 5 2 20 0 1 0 28679683 113516544 19936 18446744073709551615 4194304 5184042 140735862751120 140735862745368 139852688460229 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 27714 19936 851 242 0 20276 0 Current children cumulated CPU time (s) 51 Current children cumulated vsize (KiB) 110856 [startup+52.8002 s] /proc/loadavg: 0.91 0.93 0.90 2/56 29573 /proc/meminfo: memFree=202316/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=110856 CPUtime=52.6 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 28443 7195 0 0 5233 20 5 2 20 0 1 0 28679683 113516544 20055 18446744073709551615 4194304 5184042 140735862751120 140735862745416 139852704802400 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 27714 20055 851 242 0 20276 0 Current children cumulated CPU time (s) 52.6 Current children cumulated vsize (KiB) 110856 [startup+53.6002 s] /proc/loadavg: 0.91 0.93 0.90 2/56 29573 /proc/meminfo: memFree=202316/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=111140 CPUtime=53.4 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 28581 7195 0 0 5313 20 5 2 20 0 1 0 28679683 113807360 20193 18446744073709551615 4194304 5184042 140735862751120 140735862745416 139852704801792 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 27785 20193 851 242 0 20347 0 Current children cumulated CPU time (s) 53.4 Current children cumulated vsize (KiB) 111140 [startup+54.4002 s] /proc/loadavg: 0.91 0.93 0.90 2/56 29573 /proc/meminfo: memFree=200084/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=113020 CPUtime=54.19 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 29101 7195 0 0 5392 20 5 2 20 0 1 0 28679683 115732480 20713 18446744073709551615 4194304 5184042 140735862751120 140735862748424 139852704776600 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 28255 20713 851 242 0 20817 0 Current children cumulated CPU time (s) 54.19 Current children cumulated vsize (KiB) 113020 [startup+54.8002 s] /proc/loadavg: 0.91 0.93 0.90 2/56 29573 /proc/meminfo: memFree=200084/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=113020 CPUtime=54.59 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 29121 7195 0 0 5432 20 5 2 20 0 1 0 28679683 115732480 20733 18446744073709551615 4194304 5184042 140735862751120 140735862748424 139852704802405 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 28255 20733 851 242 0 20817 0 Current children cumulated CPU time (s) 54.59 Current children cumulated vsize (KiB) 113020 [startup+54.9002 s] /proc/loadavg: 0.91 0.93 0.90 2/56 29573 /proc/meminfo: memFree=200084/1022884 swapFree=0/0 [pid=29553] ppid=29552 vsize=80248 CPUtime=54.69 /proc/29553/stat : 29553 (cupt) R 29552 29553 17872 34816 17872 4202496 29137 7195 0 0 5442 20 5 2 20 0 1 0 28679683 82173952 13480 18446744073709551615 4194304 5184042 140735862751120 140735862749496 139852704852287 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/29553/statm: 20062 13480 862 242 0 12624 0 Current children cumulated CPU time (s) 54.69 Current children cumulated vsize (KiB) 80248 Child status: 1 Real time (s): 54.9931 CPU time (s): 54.7954 CPU user time (s): 54.5514 CPU system time (s): 0.244015 CPU usage (%): 99.6406 Max. virtual memory (cumulated for all children) (KiB): 113020 getrusage(RUSAGE_CHILDREN,...) data: user time used= 54.5514 system time used= 0.244015 maximum resident set size= 82996 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 36352 page faults= 0 swaps= 0 block input operations= 0 block output operations= 8 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 52 involuntary context switches= 840 runsolver used 0.048003 second user time and 0.180011 second system time The end