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/18.runsolver.cupt cupt -o APT::Architecture=i386 -s -V -y --no-install-recommends install gettext xstow freewnn-kserver holotz-castle-milanb tetrinet-client 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.98 0.98 2/55 2742 /proc/meminfo: memFree=539256/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=3152 CPUtime=0 /proc/2742/stat : 2742 (runsolver) R 2741 17872 17872 34816 17872 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29969442 3227648 32 18446744073709551615 134512640 134586868 4290733216 4290731264 4151391280 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.124329 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2742 /proc/meminfo: memFree=539256/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=33640 CPUtime=0.14 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 1867 7198 0 0 6 1 5 2 20 0 1 0 29969442 34447360 1685 18446744073709551615 4194304 5184042 140736724210560 140736724207752 140346037100945 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 8410 1685 729 242 0 972 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 33640 [startup+0.200299 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2742 /proc/meminfo: memFree=539256/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=35492 CPUtime=0.23 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 2330 7198 0 0 14 2 5 2 20 0 1 0 29969442 36343808 2147 18446744073709551615 4194304 5184042 140736724210560 140736724207752 140346037511920 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 8873 2147 729 242 0 1435 0 Current children cumulated CPU time (s) 0.23 Current children cumulated vsize (KiB) 35492 [startup+0.300287 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2742 /proc/meminfo: memFree=539256/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=37984 CPUtime=0.32 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 3031 7198 0 0 22 3 5 2 20 0 1 0 29969442 38895616 2785 18446744073709551615 4194304 5184042 140736724210560 140736724207752 140346054377194 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 9496 2785 739 242 0 2058 0 Current children cumulated CPU time (s) 0.32 Current children cumulated vsize (KiB) 37984 [startup+0.700193 s] /proc/loadavg: 0.99 0.98 0.98 2/55 2742 /proc/meminfo: memFree=539256/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=65972 CPUtime=0.73 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 10121 7198 0 0 56 10 5 2 20 0 1 0 29969442 67555328 9865 18446744073709551615 4194304 5184042 140736724210560 140736724207816 140346053510144 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 16493 9865 851 242 0 9055 0 Current children cumulated CPU time (s) 0.73 Current children cumulated vsize (KiB) 65972 [startup+1.5002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=502800/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=66740 CPUtime=1.51 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 10463 7198 0 0 134 10 5 2 20 0 1 0 29969442 68341760 10013 18446744073709551615 4194304 5184042 140736724210560 140736724208008 140346053510699 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 16685 10013 851 242 0 9247 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 66740 [startup+3.10021 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=501684/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=68480 CPUtime=3.11 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 11082 7198 0 0 294 10 5 2 20 0 1 0 29969442 70123520 10375 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346053533091 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 17120 10375 851 242 0 9682 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 68480 [startup+6.3002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=498336/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=72360 CPUtime=6.3 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 12381 7198 0 0 611 12 5 2 20 0 1 0 29969442 74096640 11161 18446744073709551615 4194304 5184042 140736724210560 140736724204856 140346053466548 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 18090 11161 851 242 0 10652 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 72360 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=494988/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=77424 CPUtime=12.67 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 14168 7198 0 0 1247 13 5 2 20 0 1 0 29969442 79282176 11923 18446744073709551615 4194304 5184042 140736724210560 140736724207992 140346053510794 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 19356 11923 851 242 0 11918 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 77424 [startup+25.5002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=490152/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=86548 CPUtime=25.42 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 17426 7198 0 0 2521 14 5 2 20 0 1 0 29969442 88625152 13132 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346053510908 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 21637 13132 851 242 0 14199 0 Current children cumulated CPU time (s) 25.42 Current children cumulated vsize (KiB) 86548 [startup+51.1002 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=481720/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=103064 CPUtime=50.91 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 23533 7198 0 0 5067 17 5 2 20 0 1 0 29969442 105537536 15142 18446744073709551615 4194304 5184042 140736724210560 140736724207992 140346053518637 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 25766 15142 851 242 0 18328 0 Current children cumulated CPU time (s) 50.91 Current children cumulated vsize (KiB) 103064 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=465476/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=103464 CPUtime=101.91 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 27595 7198 0 0 10163 21 5 2 20 0 1 0 29969442 105947136 19204 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346045599131 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 25866 19204 851 242 0 18428 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 103464 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=447000/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=136364 CPUtime=161.66 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 40446 7198 0 0 16133 26 5 2 20 0 1 0 29969442 139636736 23862 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346045980126 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 34091 23862 851 242 0 26653 0 Current children cumulated CPU time (s) 161.66 Current children cumulated vsize (KiB) 136364 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=427780/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=202428 CPUtime=221.42 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 61575 7198 0 0 22099 36 5 2 20 0 1 0 29969442 207286272 28606 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346053526387 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 50607 28606 851 242 0 43169 0 Current children cumulated CPU time (s) 221.42 Current children cumulated vsize (KiB) 202428 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=409428/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=202560 CPUtime=281.18 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 66240 7198 0 0 28071 40 5 2 20 0 1 0 29969442 207421440 33271 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346053510892 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 50640 33271 851 242 0 43202 0 Current children cumulated CPU time (s) 281.18 Current children cumulated vsize (KiB) 202560 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=403724/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=202560 CPUtime=298.81 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 67612 7198 0 0 29832 42 5 2 20 0 1 0 29969442 207421440 34643 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346037166528 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 50640 34643 851 242 0 43202 0 Current children cumulated CPU time (s) 298.81 Current children cumulated vsize (KiB) 202560 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: 0.99 0.98 0.98 2/56 2762 /proc/meminfo: memFree=403724/1022884 swapFree=0/0 [pid=2742] ppid=2741 vsize=202560 CPUtime=298.81 /proc/2742/stat : 2742 (cupt) R 2741 2742 17872 34816 17872 4202496 67612 7198 0 0 29832 42 5 2 20 0 1 0 29969442 207421440 34643 18446744073709551615 4194304 5184042 140736724210560 140736724207864 140346037166528 0 0 0 0 0 0 0 17 0 0 0 0 0 0 /proc/2742/statm: 50640 34643 851 242 0 43202 0 Current children cumulated CPU time (s) 298.81 Current children cumulated vsize (KiB) 202560 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.015 CPU time (s): 298.831 CPU user time (s): 298.379 CPU system time (s): 0.452028 CPU usage (%): 99.6053 Max. virtual memory (cumulated for all children) (KiB): 202560 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.379 system time used= 0.452028 maximum resident set size= 175844 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 74810 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= 4481 runsolver used 0.092005 second user time and 1.12007 second system time The end