001: /*
002: * <copyright>
003: *
004: * Copyright 1997-2004 BBNT Solutions, LLC
005: * under sponsorship of the Defense Advanced Research Projects
006: * Agency (DARPA).
007: *
008: * You can redistribute this software and/or modify it under the
009: * terms of the Cougaar Open Source License as published on the
010: * Cougaar Open Source Website (www.cougaar.org).
011: *
012: * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
013: * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
014: * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
015: * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
016: * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
017: * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
018: * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
019: * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
020: * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
021: * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
022: * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
023: *
024: * </copyright>
025: */
026: package org.cougaar.tools.csmart.runtime.plugin;
027:
028: import org.cougaar.core.blackboard.Directive;
029: import org.cougaar.core.blackboard.DirectiveMessage;
030: import org.cougaar.core.blackboard.IncrementalSubscription;
031: import org.cougaar.core.component.ServiceRevokedEvent;
032: import org.cougaar.core.component.ServiceRevokedListener;
033: import org.cougaar.core.mts.Message;
034: import org.cougaar.core.mts.MessageAddress;
035: import org.cougaar.core.mts.MessageTransportWatcher;
036: import org.cougaar.core.service.BlackboardMetricsService;
037: import org.cougaar.core.service.MessageStatisticsService;
038: import org.cougaar.core.service.MessageWatcherService;
039: import org.cougaar.core.service.NodeMetricsService;
040: import org.cougaar.planning.ldm.asset.AbstractAsset;
041: import org.cougaar.planning.ldm.asset.Asset;
042: import org.cougaar.planning.ldm.plan.Allocation;
043: import org.cougaar.planning.ldm.plan.AllocationResult;
044: import org.cougaar.planning.ldm.plan.AspectType;
045: import org.cougaar.planning.ldm.plan.Notification;
046: import org.cougaar.planning.ldm.plan.PlanElement;
047: import org.cougaar.planning.ldm.plan.Role;
048: import org.cougaar.planning.ldm.plan.Task;
049: import org.cougaar.planning.ldm.plan.Verb;
050: import org.cougaar.planning.ldm.plan.AspectValue;
051: import org.cougaar.planning.service.PrototypeRegistryService;
052: import org.cougaar.tools.csmart.runtime.jni.CpuClock;
053: import org.cougaar.util.UnaryPredicate;
054:
055: import java.io.File;
056: import java.io.FileWriter;
057: import java.io.IOException;
058: import java.io.PrintWriter;
059: import java.text.DecimalFormat;
060: import java.text.NumberFormat;
061: import java.util.Enumeration;
062: import java.util.HashSet;
063: import java.util.Set;
064: import java.util.Vector;
065:
066: /**
067: * Collect statistics on Agent operation. <br>
068: * This Plugin should be included in each Agent for which you want to collect statistics.<br>
069: * Note that some statistics are per-Node however.<br><br>
070: * This plugin is driven by control tasks, sent from a single instance of the
071: * <code>MetricsInitializerPlugin</code>. <br>
072: * Statistics are written to the standard log file, and also written, one line per sample,
073: * to a separate statistics results file.<br>
074: * The file written is named <AgentID>_results.txt.<br>
075: * If provided, the first parameter indicates the directory
076: * in which to write the file. By default, it is written
077: * in the working directory.<br>
078: * The following statistics are always written:<br>
079: * Sample length in seconds<br>
080: * CPU seconds used by Node during sample<br>
081: * (NOTE: This CPU statistic required the separate CpuClock shared library,
082: * included with the this module. If you do not compile and install
083: * this library, you will see a warning exception, which can be ignored.<br>
084: * <br>x1
085: * Memory used by Node in Megabytes<br>
086: * Total memory allocated to the Node in megabytes<br>
087: * <br>
088: * Then come some statistics recorded only if the MessageStatisticsService was requested,
089: * which is the default setting:<Br>
090: * Message Queue Length (a per-Node statistic)<br>
091: * MessageBytes Sent (per-Node)<br>
092: * Messages sent (per-Node)<br>
093: * <br>
094: * Then this statistic is always written:<br>
095: * Count of non-Metrics related Tasks with an associated high-confidence <code>AllocationResult</code><br>
096: * <br>
097: * Optional argument, statistics: If a second optional parameter is given, the
098: * plugin will count the tasks with the given Verb that go by.<br>
099: * It will also count the time since the first task with that Verb went by.<br>
100: * For example, use this to count the Transport tasks, or to see how long
101: * after a DetermineRequirements Task things get busy.<br>
102: * <br>
103: * So this optional argument results in 3 additional statistics:<br>
104: * Time since first Task with the Verb<br>
105: * Number of Tasks in this interval with the verb<br>
106: * Total Tasks seen with the verb<br>
107: * <br>
108: * Other statistics are gathered from the various services which provide
109: * measurements.<br>
110: * These statistics can be turned on/off via additional optional 1/0 arguments.<br>
111: * By default however, only the basic set of statistics is gathered.<br>
112: * First, Blackboard statistics (off by default): <br>
113: * Count of Assets on this Agent's Blackboard<br>
114: * PlanElements on this Blackboard<br>
115: * Tasks on the Blackboard<br>
116: * Total Objects on this Blackboard<br>
117: * <br>
118: * Prototype Registry (off by default):<br>
119: * Cached Prototypes<br>
120: * Property Providers<br>
121: * Prototype Providers<br>
122: * <br>
123: * Node Metrics (off by default): <br>
124: * Active threads in the COUGAAR group (a per-Node stat)<br>
125: * Free memory (bytes) in this Node's allocation<br>
126: * Total memory (bytes) in this Node's allocation<br>
127: * <br>
128: * Message Watcher (off by default): <br>
129: * Directives received by this Agent<br>
130: * Directives sent<br>
131: * Notifications received by this Agent<br>
132: * Notifications sent by this Agent<br>
133: * <br>
134: * So the full usage is: <br>
135: * MetricsPlugin Usage: [[<directory name to write results in>],[<Task Verb to search for>],
136: * [<1 or 0>], [<1 or 0>],[<1 or 0>],[<1 or 0>],[<1 or 0>]] -- where the [1/0] indicates
137: * turning on or off the following services for Metrics collection: BlackboardService,
138: * PrototypeRegistryService, NodeMetricsService, MessageStatsService, and
139: * MessageWatcherService. Default is to use only the MessageStatsService<br>
140: * <br>
141: * @see CSMARTPlugin
142: * @see MetricsConstants
143: * @see MetricsInitializerPlugin
144: */
145: public class MetricsPlugin extends CSMARTPlugin implements
146: MetricsConstants {
147: public static final String RESULTS_FILENAME_SUFFIX = "_results.txt";
148: // private static String DEFAULT_DIRECTORY = System.getProperty("org.cougaar.workspace", ".");
149: // See bug 1668 and related comments in CSMARTConsole
150: private static final String DEFAULT_DIRECTORY = ".";
151: private Role MetricsProviderRole = Role_MetricsProvider;
152: private Asset dummyAsset; // We assign the statistics tasks to this asset
153: private MessageAddress ourAgent;
154: private long startTime;
155: private long startCPU;
156: private int completedPlanElementCount = 0; // Count of completed plan elements for (manage tasks)
157: private int startPlanElementCount = 0; // count since last stats record
158: private Set completedPlanElements = new HashSet();
159: private PrintWriter writer; // write out the metrics
160:
161: // Services to use to get metrics
162: private PrototypeRegistryService protoRegistryService = null;
163: private BlackboardMetricsService bbMetricsService = null;
164: private MessageStatisticsService messageStatsService = null;
165: private MessageWatcherService messageWatchService = null;
166: private NodeMetricsService nodeMetricsService = null;
167:
168: // Flags to indicate which optional metrics to collect
169: private boolean wantBBStats = false;
170: private boolean wantProtoRegStats = false;
171: private boolean wantNodeStats = false;
172: private boolean wantMessStats = true; //default statistics obtained
173: private boolean wantMessWatchStats = false;
174:
175: boolean started = false; // dont call start twice by mistake
176:
177: static NumberFormat timeFormat = new DecimalFormat("0.000 seconds");
178: static NumberFormat memoryFormat = new DecimalFormat("0.000 MBi");
179:
180: private int countMyTasks = 0;
181: private int countMyTasksThisInterval = 0;
182: private long timeFirstMyTask = 0l;
183: private String searchVerb = null;
184:
185: // This plugin only wants the statistics gathering tasks.
186: private IncrementalSubscription myTasks;
187: public UnaryPredicate myTasksPredicate = new UnaryPredicate() {
188: public boolean execute(Object o) {
189: if (o instanceof Task) {
190: Task task = (Task) o;
191: Verb verb = task.getVerb();
192: if (verb.equals(Verb_Start) || verb.equals(Verb_Finish)
193: || verb.equals(Verb_Sample)
194: || verb.equals(Verb_Ready)) {
195: Asset directObject = (Asset) task.getDirectObject();
196: if (directObject.hasClusterPG()) {
197: MessageAddress theAgent = directObject
198: .getClusterPG().getMessageAddress();
199: if (theAgent.equals(ourAgent)) {
200: return true;
201: }
202: } else {
203: return false;
204: }
205: }
206: }
207: return false;
208: }
209: };
210:
211: private IncrementalSubscription myTaskSearch = null;
212: private UnaryPredicate taskSearchPred;
213:
214: private UnaryPredicate createTSPred(final String sverb) {
215: return new UnaryPredicate() {
216: public boolean execute(Object o) {
217: if (o instanceof Task) {
218: Task task = (Task) o;
219: Verb verb = task.getVerb();
220: if (verb.equals(sverb))
221: return true;
222: }
223: return false;
224: }
225: };
226: }
227:
228: // Predicate looks for manage plan elements
229: private IncrementalSubscription managePlanElements;
230: private static UnaryPredicate managePlanElementsPredicate = new UnaryPredicate() {
231: public boolean execute(Object o) {
232: if (o instanceof PlanElement) {
233: PlanElement pe = (PlanElement) o;
234: Task task = pe.getTask();
235: Verb verb = task.getVerb();
236: // We want to count non-control tasks
237: if (verb.equals(Verb_Start) || verb.equals(Verb_Finish)
238: || verb.equals(Verb_Sample)
239: || verb.equals(Verb_Ready)) {
240: return false;
241: } else {
242: // This is not a control task. The Scalability stuff here checks for the Verb_Manage.
243: // But for us, this should be OK.
244: return true;
245: }
246: }
247: return false;
248: }
249: };
250:
251: public void setupSubscriptions() {
252: // Is this necessary?
253: // This asset, in this plugin, is only used to be the place
254: // control tasks are allocated to
255: Asset prototype = theLDMF.createPrototype(AbstractAsset.class,
256: "Statistics");
257: dummyAsset = theLDMF.createInstance(prototype);
258: publishAdd(dummyAsset);
259:
260: ourAgent = getAgentIdentifier();
261:
262: // Open up the file for the results
263: String path = DEFAULT_DIRECTORY;
264: Vector params = getParameters() != null ? new Vector(
265: getParameters()) : null;
266: if (params != null && !params.isEmpty()) {
267: path = ((!(params.elementAt(0) instanceof String)) ? path
268: : (String) params.elementAt(0));
269: // could do File.isDirectory() and File.canWrite() on this
270:
271: // Optional second argument - verb for which tasks are searched for
272: if (params.size() > 1) {
273: // 2nd slot, number 1
274: searchVerb = (String) params.elementAt(1);
275: if (searchVerb.equals("") || searchVerb.equals(" "))
276: searchVerb = null;
277: }
278:
279: // Take the additional parameters here
280: if (params.size() > 2) {
281: if (params.size() >= 3) {
282: // Blackboard statistics are the 3rd parameter, number 2
283: if (Integer.parseInt((String) params.elementAt(2)) != 0) {
284: wantBBStats = true;
285: bbMetricsService = (BlackboardMetricsService) getServiceBroker()
286: .getService(this ,
287: BlackboardMetricsService.class,
288: new ServiceRevokedListener() {
289: public void serviceRevoked(
290: ServiceRevokedEvent re) {
291: if (BlackboardMetricsService.class
292: .equals(re
293: .getService())) {
294: bbMetricsService = null;
295: }
296: }
297: });
298: } // end of parsed non-0 int
299: } // end of have at least 3 params
300:
301: if (params.size() >= 4) {
302: // ProtypeRegistry stats are the 4th parameter, number 3
303: if (Integer.parseInt((String) params.elementAt(3)) != 0) {
304: wantProtoRegStats = true;
305: protoRegistryService = (PrototypeRegistryService) getServiceBroker()
306: .getService(this ,
307: PrototypeRegistryService.class,
308: new ServiceRevokedListener() {
309: public void serviceRevoked(
310: ServiceRevokedEvent re) {
311: if (PrototypeRegistryService.class
312: .equals(re
313: .getService()))
314: protoRegistryService = null;
315: }
316: });
317:
318: } // end of parsed non-0 int
319: } // end of if have at least 4 params
320:
321: if (params.size() >= 5) {
322: // Node metrics stats are the 5th param, number 4
323: if (Integer.parseInt((String) params.elementAt(4)) != 0) {
324: wantNodeStats = true;
325: nodeMetricsService = (NodeMetricsService) getServiceBroker()
326: .getService(this ,
327: NodeMetricsService.class,
328: new ServiceRevokedListener() {
329: public void serviceRevoked(
330: ServiceRevokedEvent re) {
331: if (NodeMetricsService.class
332: .equals(re
333: .getService())) {
334: nodeMetricsService = null;
335: }
336: }
337: });
338:
339: } // end of if parsed non-0 int
340: } // end of if have at least 5 params
341:
342: if (params.size() >= 6) {
343: // Message Transport stats are the 6th parameter, number 5: They are the only one ON by default
344: if (Integer.parseInt((String) params.elementAt(5)) == 0) {
345: wantMessStats = false;
346: }
347: }
348:
349: if (params.size() == 7) {
350: // Message Watcher statistics are the 7th parameter, number 6
351: if (Integer.parseInt((String) params.elementAt(6)) != 0) {
352: wantMessWatchStats = true;
353:
354: messageWatchService = (MessageWatcherService) getServiceBroker()
355: .getService(this ,
356: MessageWatcherService.class,
357: new ServiceRevokedListener() {
358: public void serviceRevoked(
359: ServiceRevokedEvent re) {
360: if (MessageWatcherService.class
361: .equals(re
362: .getService()))
363: messageWatchService = null;
364: }
365: });
366: messageWatchService
367: .addMessageTransportWatcher(_messageWatcher = new MessageWatcher());
368: } // end of if parsed non-0 int
369: } // end of if have 7 params
370:
371: } // end of if have more than 2 params
372:
373: if (params.size() > 7) {
374: if (log.isErrorEnabled()) {
375: // Explain the parameters correctly...
376: // wantBBStats
377: // wantProtoRegStats
378: // wantNodeStats
379: // wantMessStats -- ON by default
380: // wantMessWatchStats
381: log
382: .error("MetricsPlugin Usage: [[<directory name to write results in>],[<Task Verb to search for>],[<1 or 0>], [<1 or 0>],[<1 or 0>],[<1 or 0>],[<1 or 0>]] -- where the [1/0] indicates turning on or off the following services for Metrics collection: BlackboardService, ProtypeRegistryService, NodeMetricsService, MessageStatsService, and MessageWatcherService. Default is to use only the MessageStatsService");
383: }
384: // return;
385: }
386: }
387: // If the path doesn't end in the separator character, add one
388: if (path.lastIndexOf(File.separatorChar) != path.length() - 1) {
389: path = path + File.separator;
390: }
391:
392: if (log.isDebugEnabled()) {
393: log.debug("Writing " + path + ourAgent
394: + RESULTS_FILENAME_SUFFIX);
395: }
396:
397: try {
398: writer = new PrintWriter(new FileWriter(path + ourAgent
399: + RESULTS_FILENAME_SUFFIX));
400: } catch (IOException ioe) {
401: if (log.isDebugEnabled()) {
402: log.debug("Fatal IOException opening statistics file: "
403: + path + ourAgent + RESULTS_FILENAME_SUFFIX);
404: }
405: // should this really exit?
406: //System.exit(1);
407: }
408:
409: managePlanElements = (IncrementalSubscription) subscribe(managePlanElementsPredicate);
410: myTasks = (IncrementalSubscription) subscribe(myTasksPredicate);
411:
412: // Subscribe to tasks with the given verb
413: if (searchVerb != null) {
414: myTaskSearch = (IncrementalSubscription) subscribe(createTSPred(searchVerb));
415: }
416:
417: // startStatistics();
418: if (wantMessStats) {
419: messageStatsService = (MessageStatisticsService) getBindingSite()
420: .getServiceBroker().getService(this ,
421: MessageStatisticsService.class,
422: new ServiceRevokedListener() {
423: public void serviceRevoked(
424: ServiceRevokedEvent re) {
425: if (MessageStatisticsService.class
426: .equals(re.getService())) {
427: messageStatsService = null;
428: }
429: }
430: });
431: if (log.isDebugEnabled()) {
432: log.debug(": MessageStatsService is: "
433: + messageStatsService);
434: }
435: } // end of block on messStats
436: } // end of setupSubscriptions()
437:
438: // process statistics tasks and count completed planelements
439: public void execute() {
440: // Count up the PlanElements for our statistics
441: if (managePlanElements.hasChanged()) {
442: processPlanElements(managePlanElements.getAddedList());
443: processPlanElements(managePlanElements.getChangedList());
444: // remove from our cache of PEs any removed PEs
445: removePlanElements(managePlanElements.getRemovedList());
446: }
447:
448: // Count up the tasks I see with my verb
449: if (myTaskSearch != null && myTaskSearch.hasChanged())
450: processMyTasks(myTaskSearch.getAddedList());
451:
452: // If we have any control tasks to handle, do so
453: if (myTasks.hasChanged()) {
454: processTasks(myTasks.getAddedList());
455: }
456: //sampleStatistics();
457: // finishStatistics();
458: }
459:
460: private void processMyTasks(Enumeration e) {
461: while (e.hasMoreElements()) {
462: if (timeFirstMyTask == 0)
463: timeFirstMyTask = System.currentTimeMillis();
464: countMyTasks++;
465: countMyTasksThisInterval++;
466: e.nextElement();
467: }
468: }
469:
470: // remove removed PEs from our collection
471: private void removePlanElements(Enumeration e) {
472: while (e.hasMoreElements()) {
473: PlanElement pe = (PlanElement) e.nextElement();
474: if (!completedPlanElements.remove(pe)) {
475: // completedPlanElementCount++; // Removed before we could count it.
476: }
477: }
478: }
479:
480: /**
481: * Count up PEs with high confidence Estimated ARs
482: *
483: * @param e an <code>Enumeration</code> of PlanElements
484: */
485: private void processPlanElements(Enumeration e) {
486: while (e.hasMoreElements()) {
487: PlanElement pe = (PlanElement) e.nextElement();
488: AllocationResult estAR = pe.getEstimatedResult();
489: if (estAR != null) {
490: if (estAR.getConfidenceRating() >= 1.0) {
491: if (!completedPlanElements.contains(pe)) {
492: completedPlanElements.add(pe);
493: completedPlanElementCount++;
494: }
495: }
496: }
497: }
498: }
499:
500: /**
501: * Call start/sample/finishStatistics as appropriate, and publish
502: * a new Allocation with a high confidence AR in response.
503: *
504: * @param tasks an <code>Enumeration</code> of control Tasks
505: */
506: private void processTasks(Enumeration tasks) {
507: while (tasks.hasMoreElements()) {
508: Task task = (Task) tasks.nextElement();
509: Verb verb = task.getVerb();
510: if (verb.equals(Verb_Start)) {
511: startStatistics();
512: } else if (verb.equals(Verb_Sample)) {
513: sampleStatistics();
514: } else if (verb.equals(Verb_Finish)) {
515: sampleStatistics();
516: finishStatistics();
517: } else if (verb.equals(Verb_Ready)) {
518: // No need to do anything more. By simply responding to these,
519: // the initializer Plugin knows the agent is ready
520: // so to keep the current functionality, where
521: // the LDMPlugin is the one who signals when the Agent
522: // is ready, comment out the following line
523: //continue;
524: }
525:
526: // Dummy aspect/results
527: AspectValue[] values = { AspectValue.newAspectValue(
528: AspectType.COST, 0.0) };
529: AllocationResult estAR = theLDMF.newAllocationResult(1.0, // rating
530: true, // success
531: values);
532:
533: // Create allocation of task to asset with given estimated result
534: Allocation alloc = theLDMF.createAllocation(task.getPlan(),
535: task, dummyAsset, estAR, MetricsProviderRole);
536: publishAdd(alloc);
537: }
538: }
539:
540: /**
541: * Initialize our statistics
542: *
543: */
544: private void startStatistics() {
545: if (started)
546: return;
547: started = true;
548: startTime = System.currentTimeMillis();
549: startCPU = CpuClock.cpuTimeMillis();
550:
551: // Write out column headers in output file
552: writer.print("Sample length(sec)\t");
553: writer.print("CPU used in sample (sec)\t");
554:
555: // FIXME: Next 2 overlap with Node service
556: writer.print("Mem (MB) Used\t");
557: writer.print("Total Mem Allocated to Node (MB)");
558:
559: if (wantMessStats && messageStatsService != null)
560: messageStatsService.getMessageStatistics(true);
561:
562: if (wantMessStats) {
563: writer.print("\tMsg Q Length\t");
564: writer.print("Msg Bytes Sent\t");
565: writer.print("Msgs Sent");
566: } // end of if ()
567:
568: writer.print("\tTasks Done During Sample");
569:
570: if (myTaskSearch != null) {
571: // Print headers for optional results
572: writer.print("\tTime since first Task with Verb "
573: + searchVerb + "\t");
574: writer.print("Num Tasks this Interval with Verb "
575: + searchVerb + "\t");
576: writer.print("Total Tasks seen with Verb " + searchVerb);
577: }
578:
579: if (wantBBStats) {
580: writer.print("\tTotal Blackboard Asset Count\t");
581: writer.print("Total Plan Element Count\t");
582: writer.print("Total Task Count\t");
583: writer.print("Blackboard Object Count");
584: } // end of if ()
585:
586: // FIXME What exactly are these counting?
587: if (wantProtoRegStats) {
588: writer.print("\tCached Prototype Cnt\t");
589: writer.print("Property Provider Cnt\t");
590: writer.print("Prototype Provider Cnt");
591: } // end of if ()
592:
593: if (wantNodeStats) {
594: writer.print("\tActive Thread Cnt\t");
595: // FIXME: These next 2 overlap with those above!!
596: writer.print("Free Mem (bytes)\t");
597: writer.print("Total Mem (bytes)");
598: } // end of if ()
599:
600: if (wantMessWatchStats) {
601: writer.print("\tDirectives Into Agent\t");
602: writer.print("Directives Out\t");
603: writer.print("Notifications In\t");
604: writer.print("Notifications Out");
605: } // end of if ()
606: writer.println();
607: }
608:
609: /**
610: * Close the statistics output stream
611: *
612: */
613: private void finishStatistics() {
614: writer.close();
615: if (writer.checkError()) {
616: if (log.isErrorEnabled()) {
617: log.error("Error writing statistics file");
618: }
619: }
620: }
621:
622: /**
623: * Gather and write out the current statistics
624: *
625: */
626: private void sampleStatistics() {
627: long currentTime = System.currentTimeMillis();
628:
629: // MessageStatsService
630: double averageMessageQueueLength = 0.0;
631: long totalMessageBytes = 0l;
632: long totalMessageCount = 0l;
633: if (messageStatsService != null) {
634: averageMessageQueueLength = messageStatsService
635: .getMessageStatistics(false).averageMessageQueueLength;
636: averageMessageQueueLength = (averageMessageQueueLength == -1 ? 0.0
637: : averageMessageQueueLength);
638: totalMessageBytes = messageStatsService
639: .getMessageStatistics(false).totalSentMessageBytes;
640: totalMessageBytes = (totalMessageBytes == -1 ? 0
641: : totalMessageBytes);
642: totalMessageCount = messageStatsService
643: .getMessageStatistics(false).totalSentMessageCount;
644: totalMessageCount = (totalMessageCount == -1 ? 0
645: : totalMessageCount);
646: }
647:
648: // Blackboard Statistics
649: int assetCount = 0;
650: int planElementCount = 0;
651: int bbTaskCount = 0;
652: int bbObjCount = 0;
653: if (bbMetricsService != null) {
654: assetCount = bbMetricsService
655: .getBlackboardCount(Asset.class);
656: planElementCount = bbMetricsService
657: .getBlackboardCount(PlanElement.class);
658: bbTaskCount = bbMetricsService
659: .getBlackboardCount(Task.class);
660: bbObjCount = bbMetricsService.getBlackboardCount();
661: }
662:
663: // Prototype Registry Statistics
664: int cachedPrototypeCount = 0;
665: int propProvCount = 0;
666: int protoProvCount = 0;
667: if (protoRegistryService != null) {
668: cachedPrototypeCount = protoRegistryService
669: .getCachedPrototypeCount();
670: propProvCount = protoRegistryService
671: .getPropertyProviderCount();
672: protoProvCount = protoRegistryService
673: .getPrototypeProviderCount();
674: }
675:
676: // NodeMetricsService
677: long freeMemory = 0l;
678: long totalMemory = 0l;
679: int activeThreadCount = 0;
680: // FIXME! These duplicate the Node statistics!!
681: if (nodeMetricsService != null) {
682: freeMemory = nodeMetricsService.getFreeMemory();
683: totalMemory = nodeMetricsService.getTotalMemory();
684: activeThreadCount = nodeMetricsService
685: .getActiveThreadCount();
686: } else {
687: freeMemory = Runtime.getRuntime().freeMemory();
688: totalMemory = Runtime.getRuntime().totalMemory();
689: }
690:
691: // MessageTransport Stats
692: int directivesIn = 0;
693: int directivesOut = 0;
694: int notificationsIn = 0;
695: int notificationsOut = 0;
696: if (messageWatchService != null) {
697: directivesIn = _messageWatcher.getDirectivesIn();
698: directivesOut = _messageWatcher.getDirectivesOut();
699: notificationsIn = _messageWatcher.getNotificationsIn();
700: notificationsOut = _messageWatcher.getNotificationsOut();
701: }
702:
703: long usedMemory = totalMemory - freeMemory;
704: long elapsedTime = currentTime - startTime;
705: long cpu = CpuClock.cpuTimeMillis();
706: long cpuTime = cpu - startCPU;
707: int deltaPlanElementCount = completedPlanElementCount
708: - startPlanElementCount;
709: startTime += elapsedTime;
710: startCPU += cpuTime; // aka startCPU = cpu
711: startPlanElementCount += deltaPlanElementCount;
712: writer.print(elapsedTime / 1000.0);
713: writer.print("\t");
714: writer.print(cpuTime / 1000.0);
715: writer.print("\t");
716: writer.print(usedMemory / (1024.0 * 1024.0));
717: writer.print("\t");
718: writer.print(totalMemory / (1024.0 * 1024.0));
719:
720: writer.print("\t");
721:
722: if (wantMessStats) {
723: writer.print(averageMessageQueueLength + "\t");
724: writer.print(totalMessageBytes + "\t");
725: writer.print(totalMessageCount);
726: }
727:
728: writer.print("\t");
729: writer.print(deltaPlanElementCount);
730:
731: double timeDelta = (timeFirstMyTask == 0l ? 0l : (System
732: .currentTimeMillis() - timeFirstMyTask) / 1000.0);
733: if (myTaskSearch != null) {
734: if (timeFirstMyTask == 0l) {
735: writer.print("\t-1\t");
736: } else {
737: writer.print("\t" + timeDelta + "\t");
738: }
739: writer.print(countMyTasksThisInterval + "\t");
740: writer.print(countMyTasks);
741: }
742:
743: if (wantBBStats) {
744: writer.print("\t" + assetCount);
745: writer.print("\t" + planElementCount);
746: writer.print("\t" + bbTaskCount);
747: writer.print("\t" + bbObjCount);
748: } // end of if ()
749:
750: if (wantProtoRegStats) {
751: writer.print("\t" + cachedPrototypeCount);
752: writer.print("\t" + propProvCount);
753: writer.print("\t" + protoProvCount);
754: } // end of if ()
755:
756: if (wantNodeStats) {
757: writer.print("\t" + activeThreadCount);
758: writer.print("\t" + freeMemory);
759: writer.print("\t" + totalMemory);
760: } // end of if ()
761:
762: if (wantMessWatchStats) {
763: writer.print("\t" + directivesIn);
764: writer.print("\t" + directivesOut);
765: writer.print("\t" + notificationsIn);
766: writer.print("\t" + notificationsOut);
767: } // end of if ()
768:
769: writer.println();
770:
771: if (log.isDebugEnabled()) {
772: log.debug("Duration : "
773: + timeFormat.format(elapsedTime / 1000.0)
774: + "\n"
775: + "CPU : "
776: + timeFormat.format(cpuTime / 1000.0)
777: + "\n"
778: + "Used Memory : "
779: + memoryFormat.format(usedMemory
780: / (1024.0 * 1024.0))
781: + "\n"
782: + "Total Memory : "
783: + memoryFormat.format(totalMemory
784: / (1024.0 * 1024.0)) + "\n");
785: if (wantMessStats) {
786: log.debug("Message Queue: " + averageMessageQueueLength
787: + "\n" + "Message Bytes: " + totalMessageBytes
788: + "\n" + "Message Count: " + totalMessageCount
789: + "\n");
790: }
791:
792: log.debug("Tasks Done : " + deltaPlanElementCount);
793:
794: if (myTaskSearch != null) {
795: if (timeFirstMyTask == 0l) {
796: log.debug("Time (sec) since first task of Verb "
797: + searchVerb + ": <Not seen yet>\n");
798: } else {
799: log.debug("Time (sec) since first task of Verb "
800: + searchVerb + ": " + timeDelta + "\n");
801: }
802: log.debug("Num Tasks this interval of Verb "
803: + searchVerb + ": " + countMyTasksThisInterval
804: + "\n");
805: log.debug("Total Tasks seen with Verb " + searchVerb
806: + ": " + countMyTasks + "\n");
807: }
808:
809: // Blackboard stats
810: if (wantBBStats) {
811: log.debug("Total Assets on BBoard: " + assetCount
812: + "\n");
813: log.debug("Total PlanElements on BBoard: "
814: + planElementCount + "\n");
815: log.debug("Total Tasks on BBoard: " + bbTaskCount
816: + "\n");
817: log.debug("Total Objects on BBoard: " + bbObjCount
818: + "\n");
819: }
820:
821: // ProtypeRegistryStats
822: if (wantProtoRegStats) {
823: log.debug("Cached Prototypes: " + cachedPrototypeCount
824: + "\n");
825: log
826: .debug("Property Providers: " + propProvCount
827: + "\n");
828: log.debug("Prototype Providers: " + protoProvCount
829: + "\n");
830: }
831:
832: // Node Statistics
833: if (wantNodeStats) {
834: log.debug("Active COUGAAR Threads: "
835: + activeThreadCount + "\n");
836: log.debug("Free memory in Node's allocation (bytes): "
837: + freeMemory + "\n");
838: log.debug("Total memory for Node (bytes): "
839: + totalMemory + "\n");
840: }
841:
842: // MessageWatcher Stats
843: if (wantMessWatchStats) {
844: log.debug("Directives received by Agent: "
845: + directivesIn + "\n");
846: log.debug("Directives sent by Agent: " + directivesOut
847: + "\n");
848: log.debug("Notifications received by Agent: "
849: + notificationsIn + "\n");
850: log.debug("Notifications sent by Agent: "
851: + notificationsOut + "\n");
852: }
853: }
854:
855: // reset task count variable
856: countMyTasksThisInterval = 0;
857:
858: // Flush the writer?
859: writer.flush();
860: } // end of sampleStatistics()
861:
862: protected MessageWatcher _messageWatcher = null;
863:
864: class MessageWatcher implements MessageTransportWatcher {
865:
866: MessageAddress me;
867: private int directivesIn = 0;
868: private int directivesOut = 0;
869: private int notificationsIn = 0;
870: private int notificationsOut = 0;
871:
872: public MessageWatcher() {
873: // me = getAgentIdentifier();
874: me = MetricsPlugin.this .getAgentIdentifier();
875: }
876:
877: public void messageSent(Message m) {
878: if (m.getOriginator().equals(me)) {
879: if (m instanceof DirectiveMessage) {
880: Directive[] directives = ((DirectiveMessage) m)
881: .getDirectives();
882: for (int i = 0; i < directives.length; i++) {
883: if (directives[i] instanceof Notification)
884: notificationsOut++;
885: else
886: directivesOut++;
887: }
888: }
889: }
890: } // close messageSent
891:
892: public void messageReceived(Message m) {
893: if (m.getTarget().equals(me)) {
894: if (m instanceof DirectiveMessage) {
895: Directive[] directives = ((DirectiveMessage) m)
896: .getDirectives();
897: for (int i = 0; i < directives.length; i++) {
898: if (directives[i] instanceof Notification)
899: notificationsIn++;
900: else
901: directivesIn++;
902: }
903: }
904: }
905: } // close messageReceived
906:
907: public int getDirectivesIn() {
908: return directivesIn;
909: }
910:
911: public int getDirectivesOut() {
912: return directivesOut;
913: }
914:
915: public int getNotificationsIn() {
916: return notificationsIn;
917: }
918:
919: public int getNotificationsOut() {
920: return notificationsOut;
921: }
922: } // end of MessageWatcher
923: } // end of MetricsPlugin.java
|