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/71.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install spread libffcall1 mirror gcompris cvstrac 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.88 2/55 26990 /proc/meminfo: memFree=308076/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=3152 CPUtime=0 /proc/26990/stat : 26990 (runsolver) R 26989 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28394945 3227648 33 18446744073709551615 134512640 134586868 4293211296 4293209344 4151964720 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.17429 s] /proc/loadavg: 1.00 0.99 0.88 2/55 26990 /proc/meminfo: memFree=308076/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=34700 CPUtime=0.2 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 2160 7194 0 0 11 2 3 4 20 0 1 0 28394945 35532800 1976 18446744073709551615 4194304 5184042 140736884230512 140736884227704 139751062622289 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 8675 1976 729 242 0 1237 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 34700 [startup+0.200276 s] /proc/loadavg: 1.00 0.99 0.88 2/55 26990 /proc/meminfo: memFree=308076/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=35360 CPUtime=0.22 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 2310 7194 0 0 13 2 3 4 20 0 1 0 28394945 36208640 2126 18446744073709551615 4194304 5184042 140736884230512 140736884227704 139751062567297 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 8840 2126 729 242 0 1402 0 Current children cumulated CPU time (s) 0.22 Current children cumulated vsize (KiB) 35360 [startup+0.300265 s] /proc/loadavg: 1.00 0.99 0.88 2/55 26990 /proc/meminfo: memFree=308076/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=46604 CPUtime=0.32 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 5232 7194 0 0 21 4 3 4 20 0 1 0 28394945 47722496 5040 18446744073709551615 4194304 5184042 140736884230512 140736884224952 139751062622405 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 11651 5040 835 242 0 4213 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 46604 [startup+0.7002 s] /proc/loadavg: 1.00 0.99 0.88 2/55 26990 /proc/meminfo: memFree=308076/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=58672 CPUtime=0.72 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 8258 7194 0 0 60 5 3 4 20 0 1 0 28394945 60080128 8033 18446744073709551615 4194304 5184042 140736884230512 140736884227336 139751062547896 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 14668 8033 842 242 0 7230 0 Current children cumulated CPU time (s) 0.72 Current children cumulated vsize (KiB) 58672 [startup+1.50021 s] /proc/loadavg: 1.00 0.99 0.88 2/56 27010 /proc/meminfo: memFree=277572/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=60916 CPUtime=1.52 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 8954 7194 0 0 139 6 3 4 20 0 1 0 28394945 62377984 8535 18446744073709551615 4194304 5184042 140736884230512 140736884227816 139751078958707 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 15229 8535 842 242 0 7791 0 Current children cumulated CPU time (s) 1.52 Current children cumulated vsize (KiB) 60916 [startup+3.10021 s] /proc/loadavg: 1.00 0.99 0.88 2/56 27010 /proc/meminfo: memFree=276332/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=61940 CPUtime=3.11 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 9434 7194 0 0 298 6 3 4 20 0 1 0 28394945 63426560 8758 18446744073709551615 4194304 5184042 140736884230512 140736884227944 139751062556981 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 15485 8758 842 242 0 8047 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 61940 [startup+6.3002 s] /proc/loadavg: 1.00 0.99 0.88 2/57 27019 /proc/meminfo: memFree=273472/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=65064 CPUtime=6.2 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 10625 7194 0 0 607 6 3 4 20 0 1 0 28394945 66625536 9436 18446744073709551615 4194304 5184042 140736884230512 140736884227816 139751078984908 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 16266 9436 842 242 0 8828 0 Current children cumulated CPU time (s) 6.2 Current children cumulated vsize (KiB) 65064 [startup+12.7002 s] /proc/loadavg: 1.08 1.00 0.88 3/56 27154 /proc/meminfo: memFree=263544/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=74876 CPUtime=10.74 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 13839 7194 0 0 1059 8 3 4 20 0 1 0 28394945 76673024 11625 18446744073709551615 4194304 5184042 140736884230512 140736884224760 139751078875549 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 18719 11625 842 242 0 11281 0 Current children cumulated CPU time (s) 10.74 Current children cumulated vsize (KiB) 74876 Solver just ended. Dumping a history of the last processes samples [startup+12.8003 s] /proc/loadavg: 1.08 1.00 0.88 3/56 27154 /proc/meminfo: memFree=263544/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=74876 CPUtime=10.79 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 13844 7194 0 0 1064 8 3 4 20 0 1 0 28394945 76673024 11630 18446744073709551615 4194304 5184042 140736884230512 140736884224760 139751078847690 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 18719 11630 842 242 0 11281 0 Current children cumulated CPU time (s) 10.79 Current children cumulated vsize (KiB) 74876 [startup+16.0002 s] /proc/loadavg: 1.15 1.02 0.89 2/56 27234 /proc/meminfo: memFree=263188/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=74876 CPUtime=12.97 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 14064 7194 0 0 1281 9 3 4 20 0 1 0 28394945 76673024 11850 18446744073709551615 4194304 5184042 140736884230512 140736884223928 139751078847825 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 18719 11850 842 242 0 11281 0 Current children cumulated CPU time (s) 12.97 Current children cumulated vsize (KiB) 74876 [startup+19.2002 s] /proc/loadavg: 1.14 1.02 0.89 2/56 27234 /proc/meminfo: memFree=261204/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=83756 CPUtime=16.16 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 16640 7194 0 0 1599 10 3 4 20 0 1 0 28394945 85766144 12377 18446744073709551615 4194304 5184042 140736884230512 140736884227816 139751078919060 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 20939 12377 842 242 0 13501 0 Current children cumulated CPU time (s) 16.16 Current children cumulated vsize (KiB) 83756 [startup+20.0002 s] /proc/loadavg: 1.14 1.02 0.89 2/56 27234 /proc/meminfo: memFree=257608/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=87228 CPUtime=16.96 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 17634 7194 0 0 1678 11 3 4 20 0 1 0 28394945 89321472 13371 18446744073709551615 4194304 5184042 140736884230512 140736884227816 139751079500618 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 21807 13371 842 242 0 14369 0 Current children cumulated CPU time (s) 16.96 Current children cumulated vsize (KiB) 87228 [startup+20.8002 s] /proc/loadavg: 1.14 1.02 0.89 2/56 27234 /proc/meminfo: memFree=257608/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=93076 CPUtime=17.76 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 19190 7194 0 0 1758 11 3 4 20 0 1 0 28394945 95309824 14927 18446744073709551615 4194304 5184042 140736884230512 140736884224808 139751078847517 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 23269 14927 842 242 0 15831 0 Current children cumulated CPU time (s) 17.76 Current children cumulated vsize (KiB) 93076 [startup+21.2002 s] /proc/loadavg: 1.14 1.02 0.89 2/56 27234 /proc/meminfo: memFree=250540/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=93076 CPUtime=18.16 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 19248 7194 0 0 1798 11 3 4 20 0 1 0 28394945 95309824 14985 18446744073709551615 4194304 5184042 140736884230512 140736884224728 139751078875549 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 23269 14985 842 242 0 15831 0 Current children cumulated CPU time (s) 18.16 Current children cumulated vsize (KiB) 93076 [startup+21.3006 s] /proc/loadavg: 1.14 1.02 0.89 2/56 27234 /proc/meminfo: memFree=250540/1022884 swapFree=0/0 [pid=26990] ppid=26989 vsize=76428 CPUtime=18.26 /proc/26990/stat : 26990 (cupt) R 26989 26990 17872 34816 17872 4202496 19263 7194 0 0 1807 12 3 4 20 0 1 0 28394945 78262272 8420 18446744073709551615 4194304 5184042 140736884230512 140736884229992 139751062922730 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/26990/statm: 19107 8420 853 242 0 11669 0 Current children cumulated CPU time (s) 18.26 Current children cumulated vsize (KiB) 76428 Child status: 1 Real time (s): 21.3062 CPU time (s): 18.2691 CPU user time (s): 18.1051 CPU system time (s): 0.16401 CPU usage (%): 85.7456 Max. virtual memory (cumulated for all children) (KiB): 93076 getrusage(RUSAGE_CHILDREN,...) data: user time used= 18.1051 system time used= 0.16401 maximum resident set size= 59996 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 26476 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= 1335 runsolver used 0.036002 second user time and 0.056003 second system time The end