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/105.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config remove libbonoboui2-common libtext-wrapi18n-perl gnome-desktop-data gsfonts libtextwrap1 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.99 2/53 29453 /proc/meminfo: memFree=385604/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=3152 CPUtime=0 /proc/29453/stat : 29453 (runsolver) R 29452 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 17368744 3227648 33 18446744073709551615 134512640 134586868 4292973904 4292971952 4151419952 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.11597 s] /proc/loadavg: 0.99 0.98 0.99 2/53 29453 /proc/meminfo: memFree=385604/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=113864 CPUtime=0.1 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 8469 0 0 0 7 3 0 0 20 0 1 0 17368744 116596736 7188 18446744073709551615 4194304 6763684 140736502766112 140736502761112 139714143700624 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 28466 7188 1043 628 0 6049 0 Current children cumulated CPU time (s) 0.1 Current children cumulated vsize (KiB) 113864 [startup+0.200253 s] /proc/loadavg: 0.99 0.98 0.99 2/53 29453 /proc/meminfo: memFree=385604/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=133632 CPUtime=0.18 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 14943 0 0 0 14 4 0 0 20 0 1 0 17368744 136839168 12125 18446744073709551615 4194304 6763684 140736502766112 140736502761192 4411810 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 33408 12125 1043 628 0 10991 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 133632 [startup+0.300274 s] /proc/loadavg: 0.99 0.98 0.99 2/53 29453 /proc/meminfo: memFree=385604/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=136212 CPUtime=0.28 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 21505 413 0 0 21 7 0 0 20 0 1 0 17368744 139481088 11829 18446744073709551615 4194304 6763684 140736502766112 140736502762088 5518020 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 34053 11829 1058 628 0 10606 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 136212 [startup+0.700194 s] /proc/loadavg: 0.99 0.98 0.99 2/53 29453 /proc/meminfo: memFree=385604/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=186180 CPUtime=0.69 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 35539 413 0 0 58 11 0 0 20 0 1 0 17368744 190648320 24261 18446744073709551615 4194304 6763684 140736502766112 140736502762168 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 46545 24261 1059 628 0 23098 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 186180 [startup+1.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=243856/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=289632 CPUtime=1.48 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 67587 413 0 0 130 18 0 0 20 0 1 0 17368744 296583168 50160 18446744073709551615 4194304 6763684 140736502766112 140736502762168 5511944 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 72408 50160 1059 628 0 48961 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 289632 [startup+3.10019 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=121220/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=347468 CPUtime=3.08 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 94337 413 0 0 281 27 0 0 20 0 1 0 17368744 355807232 64591 18446744073709551615 4194304 6763684 140736502766112 140736502762152 4411810 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 86867 64591 1068 628 0 63420 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 347468 [startup+6.3002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=112664/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=6.26 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98898 413 0 0 599 27 0 0 20 0 1 0 17368744 374341632 69141 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714125455066 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69141 1070 628 0 67945 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 365568 [startup+12.7002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=112540/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=12.63 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98905 413 0 0 1236 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 4414165 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 365568 [startup+25.5002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=112540/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=25.38 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98905 413 0 0 2511 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714125455066 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 25.38 Current children cumulated vsize (KiB) 365568 [startup+51.1002 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=112540/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=50.88 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98905 413 0 0 5061 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714125455066 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 50.88 Current children cumulated vsize (KiB) 365568 [startup+102.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29456 /proc/meminfo: memFree=112416/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=101.9 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98906 413 0 0 10163 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 5194010 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 365568 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29685 /proc/meminfo: memFree=111796/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=158.84 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98906 413 0 0 15857 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714125455070 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 158.84 Current children cumulated vsize (KiB) 365568 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29685 /proc/meminfo: memFree=111796/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=218.61 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98906 413 0 0 21834 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714125455090 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 218.61 Current children cumulated vsize (KiB) 365568 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29685 /proc/meminfo: memFree=111796/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=278.39 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98906 413 0 0 27812 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714125455066 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 278.39 Current children cumulated vsize (KiB) 365568 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.99 2/54 29685 /proc/meminfo: memFree=111796/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=296.02 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98907 413 0 0 29575 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714107707073 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 296.02 Current children cumulated vsize (KiB) 365568 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.99 2/54 29685 /proc/meminfo: memFree=111796/1022884 swapFree=0/0 [pid=29453] ppid=29452 vsize=365568 CPUtime=296.02 /proc/29453/stat : 29453 (smart) R 29452 29453 2806 34818 2806 4202496 98907 413 0 0 29575 27 0 0 20 0 1 0 17368744 374341632 69144 18446744073709551615 4194304 6763684 140736502766112 140736502763064 139714107707073 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/29453/statm: 91392 69144 1073 628 0 67945 0 Current children cumulated CPU time (s) 296.02 Current children cumulated vsize (KiB) 365568 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.027 CPU time (s): 296.058 CPU user time (s): 295.754 CPU system time (s): 0.304019 CPU usage (%): 98.6774 Max. virtual memory (cumulated for all children) (KiB): 365568 getrusage(RUSAGE_CHILDREN,...) data: user time used= 295.754 system time used= 0.304019 maximum resident set size= 276576 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 99320 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= 7 involuntary context switches= 5313 runsolver used 0.336021 second user time and 0.80805 second system time The end