Inspecting additional values in summary messages

Summary log message is followed by details such as following.

15 Jan 2019 10:00:07,205 61836801 [qasimnt3(3)] INFO  B2BiMetrics - Metrics for the current hour
	Total time to get data: 29877 ms
	Last request to get data took: 687 ms  (< 5000 ms is preferable)
	Maximum time to get data took: 875 ms  (< 5000 ms is preferable)
	Average time to get data: 497 ms  (< 5000 ms is preferable)
	Total number of requests for data: 60
	Requests for data in catch up mode: 0
	Events created: 297
	Total time to log events: 110 ms
	Time to log data for data last received: 16 ms  (< 3000 ms is preferable)
	Maximum time to log data: 32 ms  (< 3000 ms is preferable)
	Average time to log events: 27 ms  (< 3000 ms is preferable)
	Total events logged: 4
	Total time to get and process data: 30267 ms
	Time to get and process data for last request: 703 ms  (< 10000 ms is preferable)
	Maximum time to get and process data for a request: 875 ms  (< 10000 ms is preferable)
	Average time to process data received: 4 ms  (< 5000 ms is preferable)
	Total records received: 1094
	Records received for last request: 0
	Maximum records received for one request: 504
	Average number of records received per request: 18
	Average number of events created per request: 4
	Average number of events logged per request: 74
	Additional values (for internal use)
		AbstractHistoryHandler.logEventToDB: 110 ms
		AbstractHistoryHandler.logStatToDB: 63 ms
		AbstractHistoryHandler.processStatRecords.logEventToDB: 110 ms
		AddStat.a: 16 ms
		AddStat.b: 0 ms
		BuildEventFromStatData: 15 ms
		FgProcessRecord: 16 ms
		FgProcessRecord.a: 0 ms
		FgProcessRecord.b: 16 ms
		GetHistory.a: 29939 ms
		GetHistory.b: 32 ms
		GetHistory.c: 0 ms
		GetResults.a: 0 ms
		GetResults.b: 29877 ms
		GetResults.c: 0 ms
		GetResults.d: 0 ms
		GetResults.e: 31 ms
		GetResults.f: 0 ms
		GetResults.g: 31 ms
		GetResults.h: 0 ms
		GetResults.i: 0 ms
		GetResults.j: 0 ms
		GetResults.k: 0 ms
		MergeEventResults: 0 ms
		MergeEventResults.sort: 0 ms
		NodeService.logEventToDB.insertNotifications: 47 ms
		NodeService.logEventToDB.rulePreProcessing: 0 ms
		ProcessData.a: 0 ms
		ProcessData.b: 29971 ms
		ProcessData.c: 0 ms
		ProcessData.d: 141 ms
		ProcessData.e: 0 ms
		ProcessStatRecord.a: 0 ms
		ProcessStatRecord.b: 16 ms
		ProcessStatRecords.a: 16 ms
		ProcessStatRecords.b: 172 ms
		SCCNotif.insertNotification: 16 ms
		SCCNotif.insertNotification-list: 47 ms
		SCCNotif.insertNotification-list.executeBatchUpdate: 47 ms
		SCCNotif.insertNotification-list.insertNotificationExt: 0 ms
		SCCNotif.insertNotification-list.keepProcessSummaryServiceInformed: 0 ms
		SCCNotif.insertNotification.executeUpdate: 16 ms
		SCCNotif.insertNotification.keepProcessSummaryServiceInformed: 0 ms
		SCCNotificationJdbcDAO.keepProcessSummaryServiceInformed: 0 ms

This information is a rehash of the summary data, with some additional values (for internal use), data which can be very helpful to further pin point areas of performance problems but can be difficult to decipher.

The following outline form of the data shown may help as indentation is used to give a breakdown of the higher-level’s time value. Note that the order of the outline does not always indicate the order of the work performed.
  • ProcessData.a – time to invoke adjustToNodeTime() which normalizes time values
  • ProcessData.b – time to invoke getHistory()
    • GetHistory.a – time to get data from server and to build stat records out of it
      • GetResults.a – time to construct request for data
      • GetResults.b – time to get response as a document and convert it to a String

        To find the amount of time to get the response, look for “ms to perform and extractFirstAttachment for” in the Engine log files

      • GetResults.c – time to build a list of Arrived file records
      • GetResults.d – time to invoke processArrivedFileRecords()
      • GetResults.e – time to build a list of Route records
      • GetResults.f – time to invoke processRouteRecords()
      • GetResults.g – time to build a list of Delivery records
      • GetResults.h – time to invoke processDeliveryRecords()
      • GetResults.i – time to build a list of Route records
      • GetResults.j – time to deduplicate the list of Route records
      • GetResults.k – time to get and process missing information
    • GetHistory.b – time to process all the stat records constructed
      • FgProcessRecord.a – time to invoke getProcessName()
      • FgProcessRecord.b (Equivalent to FgProcessRecord time)

        • AddStat.a – time to construct a GISStatistic

        • AddStat.b – time to put the GISStatistic built in appropriate data structure
    • GetHistory.c – time to order the collection of records constructed
  • ProcessData.c – time to adjust times and set sequence numbers for getHistory() results
  • ProcessData.d – time to invoke processStatRecords() which logs and processes getHistory() results
    • ProcessStatRecords.a – time to skip duplicate data
      • ProcessStatRecord.a – time to construct SCCNotification
      • ProcessStatRecord.b – time to attempt insertion of notification
        • SCCNotif.insertNotification
          • SCCNotif.insertNotification.executeUpdate
          • SCCNotif.insertNotification.insertNotificationExt
          • SCCNotif.insertNotification.keepProcessSummaryServiceInformed
    • ProcessStatRecords.b - time to process the none duplicate data
      • BuildEventFromStatData – time to construct SCCNotifications for non-dupe data
      • AbstractHistoryHandler.processStatRecords.logEventToDB
        • AbstractHistoryHandler.logStatToDB - time to update _STAT_LOG
        • AbstractHistoryHandler.logEventToDB - time to update EVENTS and more…
          • NodeService.logEventToDB.rulePreProcessing
          • NodeService.logEventToDB.insertNotifications
            • SCCNotif.insertNotification-list
              • SCCNotif.insertNotification-list.executeBatchUpdate
              • SCCNotif.insertNotification-list.insertNotificationExt
              • SCCNotif.insertNotification-list.keepProcessSummaryServiceInformed
      • Unaccounted for time is time to queue events for broadcasting
  • ProcessData.e – time to update checkpoint data
Tip: Better B2Bi monitoring performance may be obtained by limiting the protocols specified for monitoring to the ones you need data for.
Tip: Better B2Bi monitoring performance may be obtained by disabling collection of Sterling File Gateway and / or Business Process data.