4

I apologize for the title but I'm not quite sure how to ask this.

I've recently started encountering "OutOfMemoryError: Java heap space" after leaving my app running in an embedded tomcat server for a very short while.

I don't even have to query the server, I simply run mvn clean install tomcat7:run and leave the server running and the OutOfMemoryError is thrown after a few minutes.

I ran the app through a profiler (VisualVM). The server is up and running roughly around the first increase in "Heap size", the "Used heap" just keeps growing after that and until bust.

Profiler graph

Okay, so it smells like a memory leak, but during my search for answers I came across this similar question which suggests adding a SessionListener as per this example. I added this class and listener tag, ran the server and things got interesting. Immediately after the server started, the log was flooded with:

...
21:57:41.346 [http-bio-8080-exec-2] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: B9AC20CB3912D39D1AF8CEBC7D7F7ADD
21:57:41.346 [http-bio-8080-exec-2] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 148
21:57:41.352 [http-bio-8080-exec-2] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: 1A4A4EB69585E99FAE3852D3AD9D4D22
21:57:41.353 [http-bio-8080-exec-2] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 149
21:57:41.359 [http-bio-8080-exec-2] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: C48EE6DF9B0E3111AD38EAE864791C0C
21:57:41.359 [http-bio-8080-exec-2] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 150
21:57:41.365 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: D7384A391FBA06BE049AB4970EDB3E1E
21:57:41.365 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 151
21:57:41.370 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: F153AE5CC427EA1E1D67FA934E54D7AB
21:57:41.370 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 152
21:57:41.375 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: 70F1714A1010DE2AC1DAE37B191288B0
21:57:41.376 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 153
21:57:41.381 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[34] - Session created: F4C69A8E9A41CFDD59DB211BC431A409
21:57:41.381 [http-bio-8080-exec-6] DEBUG c.f.p.system.LoggingSessionListener[35] - Total sessions: 154
...

So the app is endlessly creating sessions and the profiler confirms it:

Profiler classes Profiler instances

But now I'm stuck. I've tried disabling parts of the app which seem likely culprits, although there is nothing in the app that explicitly creates sessions.

Any ideas of what could be causing this behavior, or a next step for extracting more information (such as where the Sessions are being created, if possible), will be massively appreciated, thanks!

Community
  • 1
  • 1
Liam
  • 1,041
  • 2
  • 17
  • 31
  • 2
    can you describe what your app actually does, and what kind of traffic it gets (if any)? – eis Dec 17 '13 at 21:39
  • Sure, it's a simple file host. Users can log in and upload files to the server. The server was receiving no traffic during the posted tests. – Liam Dec 17 '13 at 21:41
  • *Users can log in and* ... there's your problem. Just add more memory to your application. – Luiggi Mendoza Dec 17 '13 at 21:41
  • I've upped the heap to a gigabyte, left it running for 10 minutes with no traffic and same issue. – Liam Dec 17 '13 at 21:42
  • @LuiggiMendoza if "the server was receiving no traffic", how does users logging in have an impact? – eis Dec 17 '13 at 21:43
  • 3
    Enable and check your access log. Looks like you do get some kind of traffic because sessions don't usually get created randomly – dimoniy Dec 17 '13 at 21:44
  • @Liam can you be absolutely sure there isn't something like a heartbeat coming from load balancer or anything like that? – eis Dec 17 '13 at 21:44
  • @eis user sessions do not create themselves by magic, so something (that's not posted here) is creating those sessions and bloating the memory. – Luiggi Mendoza Dec 17 '13 at 21:45
  • Yes. But I'd be willing to bet it's not hundreds of users trying to log in. – eis Dec 17 '13 at 21:51
  • 2
    You don't have any logging in your app that does session.getSession() do you ( to get hold of a unique id for logging for example ) ? – DaveH Dec 17 '13 at 21:51
  • @DaveHowes Good suggestion but when I do a project-wide search for "getSession" the only few results that come back are from the file I added to get the logging output posted above, and in some of my tests, which aren't being run. – Liam Dec 17 '13 at 21:59
  • just to confirm, is your project the only thing deployed on the server? (there's no jrebel agents or other extra things like that) – eis Dec 17 '13 at 22:02
  • @eis It's an embedded server, started via `mvn clean install tomcat7:run` so I assume it's the only app running. – Liam Dec 17 '13 at 22:05
  • 2
    Thread is `http-bio`, so it is HTTP connection worker. It is HTTP connection creating sessions... check the HTTP traffic, inspect request, remote address, user agent, ... or sniff with Wireshark or use RequestDumperValve. – Pavel Horal Dec 17 '13 at 22:07
  • "So the app is endlessly creating sessions" - Sessions are created by the server, not the application. – a better oliver Dec 17 '13 at 22:12
  • 2
    This question appears to be off-topic because the reason were some javascript requests. Too localized. – madth3 Dec 17 '13 at 23:31
  • 2
    @madth3 Quite the contrary... this kind of questions is why SO exists. I also like the style of the question. The only OP's mistake is that he did not rule out the most obvious causes as a first step. But I am pretty sure this happened to all of us at some point. – Pavel Horal Dec 18 '13 at 08:48

1 Answers1

4

Wow I'm dumb. I had been working on a lightweight javascript resource loader for one day, but there were two glaring bugs:

  1. There was no retry limit.
  2. I forgot a "/" between the path and filename being loaded so it was endlessly requesting a non-existent file.

Anyways the loader was flooding the server with requests, which was only discovered by examining the tomcat access logs, as suggested by user @dimoniy, which revealed the horror:

127.0.0.1 - - [17/Dec/2013:17:39:34 -0500] "GET /myapp/ajax/loadjquery.js HTTP/1.1" 302 -
127.0.0.1 - - [17/Dec/2013:17:39:35 -0500] "GET /myapp/ajax/loadjquery.js HTTP/1.1" 302 -
127.0.0.1 - - [17/Dec/2013:17:39:37 -0500] "GET /myapp/ajax/loadjquery.js HTTP/1.1" 302 -
127.0.0.1 - - [17/Dec/2013:17:39:39 -0500] "GET /myapp/ajax/loadjquery.js HTTP/1.1" 302 -

So, basically I brought massive shame upon my family. Thanks to everyone who commented with suggestions!

Liam
  • 1,041
  • 2
  • 17
  • 31