Add metrics to SwingSet

[errael]

This is about application specific metrics, in particular instrumenting the library for statistics of interest. This is not about profiling, such as YourKit. I got to thinking of this wondering about how big the lists got in SSComboBox and SSDBComboBox to get an idea of the benefit of potential optimizations. I ran into a metrics library earlier this year, Metrics ... insight ... in production. It appears to be widely used in maven repository projects. There's a short Getting Started. I haven't looked at any other application instrumentation libraries.

I've run some experiments with their Histograms and Timers. Take a look at the MetricsSetup branch in my fork. Below is some example out that I got running the demo using mysql, with H2 the times were too small.

In the following, I've adapted their console reporting to output to log4j and put their CSV output into a subdirectory of the log4j output. For this report, there's no periodic collection and the reports are generated at JVM shutdown.

Using mysql, configured to only report at jvm exit

Example  of log4j output

2020-12-17 12:36:37.805 [FinalSwingSetMetrics] INFO  SwingSetMetrics.flush() - 
12/17/20, 12:36:37 PM ==========================================================

-- Histograms ------------------------------------------------------------------
com.nqadmin.swingset.SSComboBox.nItems
             count = 3
               min = 3
               max = 4
              mean = 3.67
            stddev = 0.58
            median = 4.00
              75% <= 4.00
              95% <= 4.00
              98% <= 4.00
              99% <= 4.00
            99.9% <= 4.00
com.nqadmin.swingset.SSDBComboBox.nItems
             count = 6
               min = 5
               max = 7
              mean = 5.83
            stddev = 0.75
            median = 6.00
              75% <= 6.25
              95% <= 7.00
              98% <= 7.00
              99% <= 7.00
            99.9% <= 7.00

-- Timers ----------------------------------------------------------------------
com.nqadmin.swingset.SSDBComboBox.queryTimes
             count = 6
         mean rate = 0.04 calls/second
     1-minute rate = 0.05 calls/second
     5-minute rate = 0.26 calls/second
    15-minute rate = 0.35 calls/second
               min = 0.49 milliseconds
               max = 5.25 milliseconds
              mean = 1.48 milliseconds
            stddev = 1.80 milliseconds
            median = 0.63 milliseconds
              75% <= 0.86 milliseconds
              95% <= 5.25 milliseconds
              98% <= 5.25 milliseconds
              99% <= 5.25 milliseconds
            99.9% <= 5.25 milliseconds
com.nqadmin.swingset.SSDataNavigator.updateRowTimes
             count = 7
         mean rate = 0.05 calls/second
     1-minute rate = 0.05 calls/second
     5-minute rate = 0.02 calls/second
    15-minute rate = 0.01 calls/second
               min = 0.91 milliseconds
               max = 130.49 milliseconds
              mean = 60.07 milliseconds
            stddev = 37.97 milliseconds
            median = 48.18 milliseconds
              75% <= 62.47 milliseconds
              95% <= 130.49 milliseconds
              98% <= 130.49 milliseconds
              99% <= 130.49 milliseconds
            99.9% <= 130.49 milliseconds



==========================================================

Example  of csv output

$ pwd
/f/repos/swingset/swingset/swingset-demo/log/metrics_data

$ ls
com.nqadmin.swingset.SSComboBox.nItems.csv
com.nqadmin.swingset.SSDataNavigator.updateRowTimes.csv
com.nqadmin.swingset.SSDBComboBox.nItems.csv
com.nqadmin.swingset.SSDBComboBox.queryTimes.csv

$ cat com.nqadmin.swingset.SSDBComboBox.nItems.csv
t,count,max,mean,min,stddev,p50,p75,p95,p98,p99,p999
1608237397,6,7,5.833333,5,0.752773,6.000000,6.250000,7.000000,7.000000,7.000000,7.000000

$ date --date='@1608237397'
Thu, Dec 17, 2020 12:36:37 PM

[errael]

@bpangburn I won't say let me know if you don't get this.

[bpangburn]

Do you see this as a permanent addition or something temporary where I would checkout a branch from your fork to grab some data and report back?

A little reluctant to add permanent dependencies.

[errael]

permanent addition or something temporary

Permanent. Temporary trying to keep a branch in sync doesn't seem workable.

[errael]

With unix to vxWorks to roll-your-own, I've always added some form of statisctics collection in OS work. Seems like a natural for something as dynamic as SwingSet/App. Useful for general information and tracking down specific issues, and ongoing monitoring can be useful for post mortem diagnosing when something new pops up and also as an early warning system.

I was pretty jazzed when I tried the "Timer" metric; and saw the averge/min/max time for SSDataNavigator#doUpdateRow(). The idea of collecting stats, sending them to a central collector, keeping an eye on things; seems potentially long term useful. But I don't know enough about how the app is deployed and managed.

I'm not sure about the nature of the objections to 3rd party stuff. I will note that using this kind of library is quite different from one that is user facing or that is somehow integrated into the app. In fact it does not impact the UI or the behavior of the app; it could be taken out without impacting anything.

To insure that, a layer could be devised rather than having direct calls to Metrics. Then that layer could turn itself off if Metrics is not in the class path.

[bpangburn]

Only concern is that 3rd party tools can become orphaned, but fine to add if there is justification. I like the layering idea to wall things off a bit. Certainly seems useful.

[errael]

If the time arises that instrumenting SwingSet and/or app is a thing; these notes are here.

[errael]

Forgot to mention (re-mention). What I've been using to get a feel for longer term viability of a project is https://mvnrepository.com/ . It quickly gives an idea of how widely used a project is used and how frequent it has a release.

[errael]

Came across some articles a couple weeks ago from DZone. Interesting stuff and relevant to this discussion

Logging vs. Monitoring: Part 1

Logging Best Practices: Part 2