Return-Path: Delivered-To: apmail-db-derby-commits-archive@www.apache.org Received: (qmail 99179 invoked from network); 6 Mar 2011 11:19:27 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 6 Mar 2011 11:19:27 -0000 Received: (qmail 57605 invoked by uid 500); 6 Mar 2011 11:19:27 -0000 Delivered-To: apmail-db-derby-commits-archive@db.apache.org Received: (qmail 57549 invoked by uid 500); 6 Mar 2011 11:19:26 -0000 Mailing-List: contact derby-commits-help@db.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: Reply-To: "Derby Development" List-Id: Delivered-To: mailing list derby-commits@db.apache.org Received: (qmail 57541 invoked by uid 99); 6 Mar 2011 11:19:26 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 06 Mar 2011 11:19:26 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=5.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.4] (HELO eris.apache.org) (140.211.11.4) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 06 Mar 2011 11:19:23 +0000 Received: by eris.apache.org (Postfix, from userid 65534) id B1C9723889E7; Sun, 6 Mar 2011 11:19:01 +0000 (UTC) Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Subject: svn commit: r1078449 - /db/derby/code/trunk/java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java Date: Sun, 06 Mar 2011 11:19:01 -0000 To: derby-commits@db.apache.org From: kristwaa@apache.org X-Mailer: svnmailer-1.0.8 Message-Id: <20110306111901.B1C9723889E7@eris.apache.org> X-Virus-Checked: Checked by ClamAV on apache.org Author: kristwaa Date: Sun Mar 6 11:19:01 2011 New Revision: 1078449 URL: http://svn.apache.org/viewvc?rev=1078449&view=rev Log: DERBY-5089: Improve tracing/logging of runtime exceptions raised in the istat thread Added tracing/logging of runtime exceptions and checked exceptions. Removed/added/modified some other traces. Patch file: derby-5089-1a-improved_tracing.diff Modified: db/derby/code/trunk/java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java Modified: db/derby/code/trunk/java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java URL: http://svn.apache.org/viewvc/db/derby/code/trunk/java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java?rev=1078449&r1=1078448&r2=1078449&view=diff ============================================================================== --- db/derby/code/trunk/java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java (original) +++ db/derby/code/trunk/java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java Sun Mar 6 11:19:01 2011 @@ -234,20 +234,16 @@ public class IndexStatisticsDaemonImpl */ public void schedule(TableDescriptor td) { String schedulingReason = td.getIndexStatsUpdateReason(); - trace(0, "scheduling " + td.getQualifiedName() + - (schedulingReason == null - ? "" - : " reason=[" + schedulingReason + "]")); synchronized (queue) { if (acceptWork(td)) { // Add the work description for the given table. queue.add(td); wuScheduled++; log(AS_BACKGROUND_TASK, td, - "update scheduled - " + td.getUUID() + + "update scheduled" + (schedulingReason == null ? "" - : " reason=[" + schedulingReason + "]") + + : ", reason=[" + schedulingReason + "]") + " (queueSize=" + queue.size() + ")"); // If we're idle, fire off the worker thread. if (runningThread == null) { @@ -290,16 +286,18 @@ public class IndexStatisticsDaemonImpl // If the work was rejected, trace it. if (!accept) { + String msg = td.getQualifiedName() + " rejected, "; if (daemonDisabled) { wuRejectedOther++; - trace(1, "daemon disabled - work not scheduled"); + msg += "daemon disabled"; } else if (queue.size() >= MAX_QUEUE_LENGTH) { wuRejectedFQ++; - trace(1, "queue full - work not scheduled"); + msg += "queue full"; } else { wuRejectedDup++; - trace(1, "duplicate found - not scheduled"); + msg += "duplicate"; } + trace(1, msg); } return accept; } @@ -317,7 +315,7 @@ public class IndexStatisticsDaemonImpl private void generateStatistics(LanguageConnectionContext lcc, TableDescriptor td) throws StandardException { - trace(0, "generateStatistics::start {" + td.getQualifiedName() + "}"); + trace(1, "processing " + td.getQualifiedName()); boolean lockConflictSeen = false; while (true) { try { @@ -348,7 +346,6 @@ public class IndexStatisticsDaemonImpl } } } - trace(0, "generateStatistics::end"); } /** Return true if we are being shutdown */ @@ -557,8 +554,10 @@ public class IndexStatisticsDaemonImpl // Log some information. log(asBackgroundTask, td, - "wrote stats for index " + index + " (rows=" + numRows + - ", card=" + cardToStr(cardinality) + ")"); + "wrote stats for index " + + dd.getConglomerateDescriptor(index).getDescriptorName() + + " (" + index + "): rows=" + numRows + + ", card=" + cardToStr(cardinality)); } // Only commit tx as we go if running as background task. @@ -677,6 +676,7 @@ public class IndexStatisticsDaemonImpl } catch (ShutdownException se) { // The database is/has been shut down. // Log processing statistics and exit. + trace(1, "swallowed shutdown exception: " + extractIstatInfo(se)); stop(); ctxMgr.cleanupOnError(se, db.isActive()); } catch (RuntimeException re) { @@ -687,13 +687,18 @@ public class IndexStatisticsDaemonImpl // happens because the background thread interacts with store // on a lower level if (!isShuttingDown()) { + log(AS_BACKGROUND_TASK, null, re, + "runtime exception during normal operation"); throw re; } + trace(1, "swallowed runtime exception during shutdown: " + + extractIstatInfo(re)); } finally { if (ctxService != null) { ctxService.resetCurrentContextManager(ctxMgr); } runTime += (System.currentTimeMillis() - runStart); + trace(0, "worker thread exit"); } } @@ -707,7 +712,6 @@ public class IndexStatisticsDaemonImpl try { daemonLCC = db.setupConnection(ctxMgr, dbOwner, null, databaseName); - trace(1, "got database connection"); // Initialize the lcc/transaction. // TODO: Would be nice to name the transaction. daemonLCC.setIsolationLevel( @@ -741,6 +745,7 @@ public class IndexStatisticsDaemonImpl tc = null; daemonLCC = null; queue.clear(); + trace(1, "daemon disabled"); break; } if (queue.isEmpty()) { @@ -751,7 +756,6 @@ public class IndexStatisticsDaemonImpl } try { start = System.currentTimeMillis(); - log(AS_BACKGROUND_TASK, td, "generating index statistics"); generateStatistics(daemonLCC, td); wuProcessed++; // Reset consecutive error counter. @@ -794,7 +798,6 @@ public class IndexStatisticsDaemonImpl } } } - trace(0, "run::normal_exit"); } catch (StandardException se) { log(AS_BACKGROUND_TASK, null, se, "thread died"); // Do nothing, just let the thread die. @@ -833,11 +836,11 @@ public class IndexStatisticsDaemonImpl ConglomerateDescriptor[] cds, String runContext) throws StandardException { - trace(0, "explicit run" + (runContext != null + updateIndexStatsMinion(lcc, td, cds, AS_EXPLICIT_TASK); + trace(0, "explicit run completed" + (runContext != null ? " (" + runContext + "): " - : ":") + + : ": ") + td.getQualifiedName()); - updateIndexStatsMinion(lcc, td, cds, AS_EXPLICIT_TASK); } /** @@ -894,6 +897,8 @@ public class IndexStatisticsDaemonImpl // DERBY-4037: Swallow exceptions raised during shutdown. // The database or system is going down. Probably handled elsewhere // but disable daemon anyway. + trace(1, "swallowed exception during shutdown: " + + extractIstatInfo(se)); disable = true; cm.cleanupOnError(se, db.isActive()); } @@ -926,7 +931,6 @@ public class IndexStatisticsDaemonImpl errorsKnown++; log(AS_BACKGROUND_TASK, td, "generation aborted (reason: " + state + ") {" + extractIstatInfo(se) + "}"); - trace(1, "top level expected exception: " + extractIstatInfo(se)); return true; } return false; @@ -1080,13 +1084,14 @@ public class IndexStatisticsDaemonImpl } /** Purely for debugging, to avoid printing too much info. */ - private static String extractIstatInfo(StandardException se) { - StackTraceElement[] stack = se.getStackTrace(); - String trace = ""; + private static String extractIstatInfo(Throwable t) { + String istatClass = IndexStatisticsDaemonImpl.class.getName(); + StackTraceElement[] stack = t.getStackTrace(); + String trace = ""; + String sqlState = ""; for (int i=0; i < stack.length ; i++) { StackTraceElement ste = stack[i]; - if (IndexStatisticsDaemonImpl.class.getName().equals( - ste.getClassName())) { + if (ste.getClassName().startsWith(istatClass)) { trace = ste.getMethodName() + "#" + ste.getLineNumber(); if (i > 0) { ste = stack[i -1]; @@ -1096,8 +1101,11 @@ public class IndexStatisticsDaemonImpl break; } } - return trace + " got " + se.getSQLState() + - " (" + se.getMessage() + ")"; + if (t instanceof StandardException) { + sqlState = ", SQLSTate=" + ((StandardException)t).getSQLState(); + } + return "<" + t.getClass() + ", msg=" + t.getMessage() + sqlState + + "> " + trace; } /**