Menu
▾
▴
[Hyperic-hq-discuss] hq r14404 - trunk/src/org/hyperic/hq/measurement/server/session
|
From: <pn...@hy...> - 2010-03-22 17:41:12
|
Author: pnguyen Date: 2010-03-22 10:41:03 -0700 (Mon, 22 Mar 2010) New Revision: 14404 URL: http://svn.hyperic.org/?view=rev&root=Hyperic+HQ&revision=14404 Modified: trunk/src/org/hyperic/hq/measurement/server/session/AvailabilityManagerEJBImpl.java trunk/src/org/hyperic/hq/measurement/server/session/ReportProcessorEJBImpl.java Log: [HQ-2030] Add more informational debug statements Modified: trunk/src/org/hyperic/hq/measurement/server/session/AvailabilityManagerEJBImpl.java =================================================================== --- trunk/src/org/hyperic/hq/measurement/server/session/AvailabilityManagerEJBImpl.java 2010-03-22 07:58:45 UTC (rev 14403) +++ trunk/src/org/hyperic/hq/measurement/server/session/AvailabilityManagerEJBImpl.java 2010-03-22 17:41:03 UTC (rev 14404) @@ -755,27 +755,17 @@ _createMap = new HashMap(); _removeMap = new HashMap(); final boolean debug = _log.isDebugEnabled(); - long begin = -1; Map state = null; synchronized (cache) { try { cache.beginTran(); - begin = getDebugTime(debug); updateCache(availPoints, updateList, outOfOrderAvail); - debugTimes(begin, "updateCache", availPoints.size()); - begin = getDebugTime(debug); setCurrAvails(outOfOrderAvail, updateList); - debugTimes(begin, "setCurrAvails", - outOfOrderAvail.size() + updateList.size()); state = captureCurrAvailState(); - begin = getDebugTime(debug); updateStates(updateList); - debugTimes(begin, "updateStates", updateList.size()); - begin = getDebugTime(debug); updateOutOfOrderState(outOfOrderAvail); flushCreateAndRemoves(); logErrorInfo(state, availPoints); - debugTimes(begin, "updateOutOfOrderState", outOfOrderAvail.size()); cache.commitTran(); } catch (Throwable e) { logErrorInfo(state, availPoints); @@ -791,13 +781,15 @@ ConcurrentStatsCollector.getInstance().addStat( availPoints.size(), AVAIL_MANAGER_METRICS_INSERTED); if (sendData) { - begin = getDebugTime(debug); sendDataToEventHandlers(availPoints); - debugTimes(begin, "sendDataToEventHandlers", availPoints.size()); } } private void flushCreateAndRemoves() { + final StopWatch watch = new StopWatch(); + final boolean debug = _log.isDebugEnabled(); + + if (debug) watch.markTimeBegin("remove"); for (Iterator it=_removeMap.entrySet().iterator(); it.hasNext(); ) { Map.Entry entry = (Map.Entry)it.next(); AvailabilityDataRLE rle = (AvailabilityDataRLE)entry.getValue(); @@ -810,12 +802,23 @@ _dao.remove(rle); } } + if (debug) { + watch.markTimeEnd("remove"); + watch.markTimeBegin("flush"); + } + // addData() could be overwriting RLE data points (i.e. from 0.0 to 1.0) // with the same ID. If this is the scenario, then we must run // flush() in order to ensure that these old objects are not in the // session when the equivalent create() on the same ID is run, // thus avoiding NonUniqueObjectExceptions _dao.getSession().flush(); + + if (debug) { + watch.markTimeEnd("flush"); + watch.markTimeBegin("create"); + } + for (Iterator it=_createMap.entrySet().iterator(); it.hasNext(); ) { Map.Entry entry = (Map.Entry)it.next(); AvailabilityDataRLE rle = (AvailabilityDataRLE)entry.getValue(); @@ -825,24 +828,16 @@ _dao.create(rle.getMeasurement(), rle.getStartime(), rle.getEndtime(), rle.getAvailVal()); } - } - - private long getDebugTime(final boolean debug) { + if (debug) { - return System.currentTimeMillis(); + watch.markTimeEnd("create"); + _log.debug("AvailabilityInserter flushCreateAndRemoves: " + watch + + ", points {remove=" + _removeMap.size() + + ", create=" + _createMap.size() + + "}"); } - return -1; } - private void debugTimes(final long begin, final String name, - final int points) { - if (_log.isDebugEnabled()) { - long time = System.currentTimeMillis() - begin; - _log.debug("AvailabilityInserter time to " + name + " -> " - + time + " ms, points: " + points); - } - } - private void logErrorInfo(final Map oldState, final List availPoints) { if (!_traceLog.isDebugEnabled()) { return; @@ -860,20 +855,29 @@ private void setCurrAvails(final List outOfOrderAvail, final List updateList) { - if (outOfOrderAvail.size() == 0 && updateList.size() == 0) { - _currAvails = Collections.EMPTY_MAP; - return; + + final StopWatch watch = new StopWatch(); + try { + if (outOfOrderAvail.size() == 0 && updateList.size() == 0) { + _currAvails = Collections.EMPTY_MAP; + return; + } + long now = TimingVoodoo.roundDownTime(System.currentTimeMillis(), 60000); + HashSet mids = getMidsWithinAllowedDataWindow(updateList, now); + mids.addAll(getMidsWithinAllowedDataWindow(outOfOrderAvail, now)); + if (mids.size() <= 0) { + _currAvails = Collections.EMPTY_MAP; + return; + } + Integer[] mIds = (Integer[])mids.toArray(new Integer[0]); + _currAvails = _dao.getHistoricalAvailMap( + mIds, now-MAX_DATA_BACKLOG_TIME, false); + } finally { + if (_log.isDebugEnabled()) { + _log.debug("AvailabilityInserter setCurrAvails: " + watch + + ", size=" + _currAvails.size()); + } } - long now = TimingVoodoo.roundDownTime(System.currentTimeMillis(), 60000); - HashSet mids = getMidsWithinAllowedDataWindow(updateList, now); - mids.addAll(getMidsWithinAllowedDataWindow(outOfOrderAvail, now)); - if (mids.size() <= 0) { - _currAvails = Collections.EMPTY_MAP; - return; - } - Integer[] mIds = (Integer[])mids.toArray(new Integer[0]); - _currAvails = _dao.getHistoricalAvailMap( - mIds, now-MAX_DATA_BACKLOG_TIME, false); } private HashSet getMidsWithinAllowedDataWindow(final List states, @@ -1247,7 +1251,9 @@ } // as a performance optimization, fetch all the last avails // at once, rather than one at a time in updateState() + final StopWatch watch = new StopWatch(); final boolean debug = _log.isDebugEnabled(); + int numUpdates = 0; for (Iterator i=states.iterator(); i.hasNext(); ) { DataPoint state = (DataPoint)i.next(); try { @@ -1265,26 +1271,45 @@ } if (updateCache) { cache.put(state.getMetricId(), state); + numUpdates++; } } catch (BadAvailStateException e) { _log.warn(e.getMessage()); } } + if (debug) { + _log.debug("AvailabilityInserter updateStates: " + watch + + ", points {total=" + states.size() + + ", updateCache=" + numUpdates + + "}"); + } } private void updateOutOfOrderState(List outOfOrderAvail) { if (outOfOrderAvail.size() == 0) { return; } + + final StopWatch watch = new StopWatch(); + int numBadAvailState = 0; + for (Iterator i=outOfOrderAvail.iterator(); i.hasNext(); ) { try { DataPoint state = (DataPoint)i.next(); // do not update the cache here, the timestamp is out of order merge(state); } catch (BadAvailStateException e) { + numBadAvailState++; _log.warn(e.getMessage()); } } + + if (_log.isDebugEnabled()) { + _log.debug("AvailabilityInserter updateOutOfOrderState: " + watch + + ", points {total=" + outOfOrderAvail.size() + + ", badAvailState=" + numBadAvailState + + "}"); + } } private void updateCache(List availPoints, List updateList, @@ -1294,6 +1319,7 @@ return; } AvailabilityCache cache = AvailabilityCache.getInstance(); + final StopWatch watch = new StopWatch(); final boolean debug = _log.isDebugEnabled(); for (Iterator i=availPoints.iterator(); i.hasNext(); ) { DataPoint pt = (DataPoint)i.next(); @@ -1313,19 +1339,30 @@ oldState.getValue() != val) { updateList.add(newState); if (debug) { - String msg = "value of state " + newState + - " differs from" + " current value" + + String msg = "value of state[" + newState + + "] differs from current value[" + ((oldState != null) ? oldState.toString() : - " old state does not exist"); + "old state does not exist") + "]"; _log.debug(msg); } } else { cache.put(new Integer(id), newState); } } + if (debug) { + _log.debug("AvailabilityInserter updateCache: " + watch + + ", points {total=" + availPoints.size() + + ", outOfOrder=" + outOfOrderAvail.size() + + ", updateToDb=" + updateList.size() + + ", updateCacheTimestamp=" + + (availPoints.size() - outOfOrderAvail.size() - updateList.size()) + + "}"); + } } private void sendDataToEventHandlers(List data) { + final StopWatch watch = new StopWatch(); + final boolean debug = _log.isDebugEnabled(); int maxCapacity = data.size(); ArrayList events = new ArrayList(maxCapacity); Map downEvents = new HashMap(maxCapacity); @@ -1335,8 +1372,7 @@ final boolean allEventsInteresting = Boolean.getBoolean(ALL_EVENTS_INTERESTING_PROP); - final StopWatch watch = new StopWatch(); - final boolean debug = _log.isDebugEnabled(); + if (debug) watch.markTimeBegin("isTriggerInterested"); for (Iterator i = data.iterator(); i.hasNext();) { DataPoint dp = (DataPoint) i.next(); Integer metricId = dp.getMetricId(); @@ -1344,10 +1380,8 @@ MeasurementEvent event = new MeasurementEvent(metricId, val); - if (debug) watch.markTimeBegin("isTriggerInterested"); boolean isEventInteresting = allEventsInteresting || RegisteredTriggers.isTriggerInterested(event); - if (debug) watch.markTimeEnd("isTriggerInterested"); if (isEventInteresting) { measMan.buildMeasurementEvent(event); if (event.getValue().getValue() == AVAIL_DOWN) { @@ -1362,13 +1396,16 @@ zevents.add(new MeasurementZevent(metricId.intValue(), val)); } + if (debug) watch.markTimeEnd("isTriggerInterested"); if (!downEvents.isEmpty()) { + if (debug) watch.markTimeBegin("suppressMeasurementEvents"); // Determine whether the measurement events can // be suppressed as part of hierarchical alerting PermissionManagerFactory.getInstance() .getHierarchicalAlertingManager() .suppressMeasurementEvents(downEvents, true); + if (debug) watch.markTimeEnd("suppressMeasurementEvents"); if (!downEvents.isEmpty()) { events.addAll(downEvents.values()); @@ -1383,6 +1420,15 @@ if (!zevents.isEmpty()) { ZeventManager.getInstance().enqueueEventsAfterCommit(zevents); } + + if (debug) { + _log.debug("AvailabilityInserter sendDataToEventHandlers: " + watch + + ", points {total=" + maxCapacity + + ", downEvents=" + downEvents.size() + + ", eventsToPublish=" + events.size() + + ", zeventsToEnqueue=" + zevents.size() + + "}"); + } } /** Modified: trunk/src/org/hyperic/hq/measurement/server/session/ReportProcessorEJBImpl.java =================================================================== --- trunk/src/org/hyperic/hq/measurement/server/session/ReportProcessorEJBImpl.java 2010-03-22 07:58:45 UTC (rev 14403) +++ trunk/src/org/hyperic/hq/measurement/server/session/ReportProcessorEJBImpl.java 2010-03-22 17:41:03 UTC (rev 14404) @@ -179,11 +179,10 @@ final MeasurementManagerLocal mMan = MeasurementManagerEJBImpl.getOne(); final boolean debug = _log.isDebugEnabled(); final StopWatch watch = new StopWatch(); + if (debug) watch.markTimeBegin("verifyAndAddData"); for (int i = 0; i < dsnLists.length; i++) { Integer dmId = new Integer(dsnLists[i].getClientId()); - if (debug) watch.markTimeBegin("getMeasurement"); Measurement m = mMan.getMeasurement(dmId); - if (debug) watch.markTimeEnd("getMeasurement"); // Can't do much if we can't look up the derived measurement // If the measurement is enabled, we just throw away their data @@ -192,12 +191,19 @@ // points for. This is still a problem for people who change their // collection period, but the instances should be low. if (m == null || !m.isEnabled()) { + if (debug) { + if (m == null) { + _log.debug("dropping metricId=" + dmId + + " because measurement is null"); + } else { + _log.debug("dropping metricId=" + dmId + + " because measurement is disabled"); + } + } continue; } // Need to check if resource was asynchronously deleted (type == null) - if (debug) watch.markTimeBegin("getResource"); final Resource res = m.getResource(); - if (debug) watch.markTimeEnd("getResource"); if (res == null || res.isInAsyncDeleteState()) { if (debug) { _log.debug("dropping metricId=" + m.getId() + @@ -205,20 +211,16 @@ } continue; } - if (debug) watch.markTimeBegin("resMatchesAgent"); if (!resourceMatchesAgent(res, agentToken)) { _log.warn("measurement (id=" + m.getId() + ") was sent to the " + "HQ server from agent (agentToken=" + agentToken + ")" + " but resource (id=" + res.getId() + ") is not associated " + " with that agent. Dropping measurement."); - if (debug) watch.markTimeEnd("resMatchesAgent"); continue; } - if (debug) watch.markTimeEnd("resMatchesAgent"); final boolean isAvail = m.getTemplate().isAvailability(); final ValueList[] valLists = dsnLists[i].getDsns(); - if (debug) watch.markTimeBegin("addData"); for (int j = 0; j < valLists.length; j++) { final MetricValue[] vals = valLists[j].getValues(); if (isAvail) { @@ -227,9 +229,18 @@ addData(dataPoints, null, m, vals); } } - if (debug) watch.markTimeEnd("addData"); } - if (debug) _log.debug(watch); + if (debug) { + watch.markTimeEnd("verifyAndAddData"); + _log.debug("received " + + dsnLists.length + + " metrics, processing " + + dataPoints.size() + " data points, " + + availPoints.size() + " avail points, " + + priorityAvailPts.size() + + " priority avail points from agent with token " + + agentToken); + } DataInserter d = MeasurementStartupListener.getDataInserter(); if (debug) watch.markTimeBegin("sendMetricDataToDB"); @@ -261,6 +272,7 @@ StringUtil.arrayToString(entIds)); } } + if (debug) _log.debug("handleMeasurementReport: " + watch); } /** |
