[Bug 2037] Thread count view queries all summaries for the last hour, every second.

Thu Jun 2 12:24:12 UTC 2016

http://icedtea.classpath.org/bugzilla/show_bug.cgi?id=2037

Severin Gehwolf <sgehwolf at redhat.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|Thread monitor view fails   |Thread count view queries
                   |to cancel a timer?          |all summaries for the last
                   |                            |hour, every second.

--- Comment #3 from Severin Gehwolf <sgehwolf at redhat.com> ---
I've looked into this issue again and it's not really an issue with the
time-line view. At least not exclusively.

One issue here is as follows and pertains to the thread count view.

Steps to reproduce:
0. Apply attached patch (sets logging level to FINEST and disables logging in
   MongoStorage). Build thermostat.
1. $ ./bin/thermostat local
2. Leave it running for a while. > 10 minutes will start to show the issue
3. Watch FINEST logging output for WebCursor/WebStorageEndpoint

Logging looks like this:
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (100) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
FINEST - WebCursor: Getting more results for cursorId: 202
FINEST - WebStorageEndPoint: Fetched more results (91) for user
'client-SaU7ixmM' cursorId 202. Statement: QUERY vm-thread-summary WHERE 'vmId'
= ?s AND 'agentId' = ?s AND 'timeStamp' >= ?l AND 'timeStamp' <= ?l SORT
'timeStamp' DSC LIMIT ?i
getThreadSummary() took: 67ms

This is the same cursor ID, thus the same query. Every getMore() incurs network
traffic. Perhaps the batch size for WebCursor.getMore() could get tweaked too.
But that's not really the point here.

The above query has a total return set of 1691 records, slized to 17 getMore()
calls. Thus, 17, network roundtrips. That adds up. Adjusting the batch size
only buys us so much. It's a trade-off of memory vs. network traffic.

The getMore() queries stem from the fact that we gather historical data, the
longer you let it running the larger the result set (possibly) gets. Why?
Because the query above comes from
ThreadCountController.ThreadInformationDataCollector.updateChart(). It fetches
data via collector.getThreadSummary(range) where the range is
(one-hour-from-now, now). While the query is bounded, it's still way to much
data querying - especially network round-trips with getmore - for the use-case
at hand.

The query runs every second (scheduled via a timer) and fetches results for the
last hour. However, the difference in new records is minimal. Since only a
second has passed since the last query, empirically, the delta is pretty much
one record more by-and-large. That means if that view stays open for longer
many records get repeatedly re-queried over time and those records need to
travel the network. Not good.

Suggested fixes could be:
- Query for the result set once for the initial chart drawing.
  Then only query shorter periods. Results T-1sec won't have changed.
- Update the chart less frequently. E.g. once every 10 seconds.
- Implement caching of results so as to not query redundant data sets.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/distro-pkg-dev/attachments/20160602/5df22c84/attachment-0001.html>