Performance degradation when queueing events using queueEvents(…)

[perendipity]

A user noticed a performance issue when sending events and I'm adding it here for visibility as we track this down:

I drilled down a bit in my test and I found something strange: my (Java) code seems to spend more time in queueing events queueEvents(…) than in sendQueuedEvents(…)

Below a short excerpt, times are in milliseconds:

Queuing time: 6645 Sending time: 13501
0-0 Total events: 4999 Total time: 20146 Events per second: 248.1385883053708
Queuing time: 14183 Sending time: 6875
1-0 Total events: 9998 Total time: 41205 Events per second: 242.64045625530883
Queuing time: 40750 Sending time: 6045
2-0 Total events: 14997 Total time: 88000 Events per second: 170.42045454545453
Queuing time: 69652 Sending time: 5736
3-0 Total events: 19996 Total time: 163388 Events per second: 122.38352877812324
Queuing time: 86217 Sending time: 5985
4-0 Total events: 24995 Total time: 255590 Events per second: 97.79334089753121

My test was using only one thread – so I guess. I looked at the memory usage – it seems almost constant during the test – so a memory leak is unlikely.

There seems to be a degradation in performance in one the internal collections of the Keen Java library, with every call to it.

I assumed that the KeenClient.client().sendQueuedEvents() method also clears the queue after serializing it and I did not find any clear method.

As a note, I’m using the latest Keen Java SDK, 2.1.1

[bocse]

I have drilled down in your code and I think I have found the issue in the KeenClient class which does not clear the following collection from the RamEventStore:

private Map<String, Map<String, String>> attempts;

This map contains a key for each project. The value associated to this key is another map in which the value is a JSON String of (what I assume) all the attempts made to add an event.

The problem is that this value (inside a map inside a map) is NOT cleared upon calling sendQueuedEvents in KeenClient.

Moreover, the performance issue is constituted by the fact that this JSON String is deserialized and iterated upon EACH TIME queueEvent is called (so basically for each new event added). This is like a masked memory leak, in the sense that it has relatively small, slowly-growing memory footprint, but it clogs the performance by adding an O(n) step on the event queueing operation.

The deserialization section is highlighted below.

private Map<String, Integer> getAttemptsMap(String projectId, String eventCollection) throws IOException {
    HashMap attempts = new HashMap();
    if(this.eventStore instanceof KeenAttemptCountingEventStore) {
        KeenAttemptCountingEventStore res = (KeenAttemptCountingEventStore)this.eventStore;
        String attemptsJSON = res.getAttempts(projectId, eventCollection);
        if(attemptsJSON != null) {
            StringReader reader = new StringReader(attemptsJSON);
            Map attemptTmp = this.jsonHandler.readJson(reader);
            Iterator i$ = attemptTmp.entrySet().iterator();

            while(i$.hasNext()) {
                Entry entry = (Entry)i$.next();
                if(entry.getValue() instanceof Number) {
                    attempts.put(entry.getKey(), Integer.valueOf(((Number)entry.getValue()).intValue()));
                }
            }
        }
    }

    return attempts;
}

The JSON String looks like this:
{"10997":3,"10998":3,"10999":3,"6873":2,"10990":3,"6874":2,"6871":2,"10991":3,"10992":3,"6872":2,"10993":3,"6870":2,"10994":3,"10995":3,"10996":3,"531":2,"530":2,"2951":2,"6869":2,"6868":2,"2950":2,"2953":2,"1821":2,"6867":2,"535":2,"2952":2,"534":2,"1822":2,"6866":2,"6865":2,"2955":2,"533":2,"2954":2,"532":2,"1820":2,"6864":2,"1825":2,"539":2,"2957":2,"2956":2,"538":2,"1826":2,"1823":2,"537":2,"2959":2,"2958":2,"536":2,"1824":2,"1829":2,"1827":2,"1828":2,"6882":2,"6883":2,"6884":2,"6885":2,"6880":2,"6881":2,"3":2,"540":2,"2940":2,"2":2,"6879":2,"1":2,"542":2,"0":2,"541":2,"6876":2,"7":2,"544":2,"2944":2,"6875":2,"2943":2,"6":2,"543":2,"6878":2,"5":2,"546":2,"1810":2,"2942":2,"6877":2,"4":2,"2941":2,"545":2,"1811":2,"548":2,"2948":2,"1812":2,"547":2,"1813":2,"2947":2,"9":2,"1814":2,"2946":2,"549":2,"8":2,"1815":2,"2945":2,"1816":2,"1817":2,"1818":2,"1819":2,"2949":2,"6891":2,"6892":2,"6890":

Note: without surprise, the issue manifests itself on Java 1.7 and 1.8 without difference.

[perendipity]

Hi Bogdan! Thanks again for contributing so thoroughly. I have confirmed this issue as well with some tests and will be blocking off some time to make a pull request.

[perendipity]

To close the loop here - this issue will be addressed as part of a larger SDK update that decouples the Android SDK from the Java SDK, in part because they have different serialization needs.