Play 2.2.0 Application consume more than 100% CPU in Linux

[Manikandan Kaliyaperumal]

Hi,

We have Play 2.2.0 app running on Linux VM. It has been in production for few months (6+ months) and recently we got an alert from our monitoring that this VM is 140% CPU utilization.

We did some initial analysis and took thread dump for the services that are on high CPU. And found that the Play Scheduler threads are the ones causing high CPU utilization.

Please find below the details: 

Java PID's that are consuming high CPU:

33338 gse       20   0 5686m 1.6g 9296 S 141.2 13.5  24189:42 java à (eqx-cache-fase-lib-1.1)

33680 gse       20   0 5791m 2.7g 9484 S 131.3 23.5  23574:17 java à (eqx-content-fase-lib-1.1)

36601 gse       20   0 4307m 1.9g 9088 S 125.0 16.8  21948:42 java à (eqx-fase-db-connect-1.0)

 

High CPU utilization with Thread Level break up on:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

26793 gse       20   0  551m 7308 2352 S 200.0  0.1   0:00.01 bonobo-activati

2238 root      20   0 2033m 2464 2004 S 6400.0  0.0   0:34.77 console-kit-dae

1775 root      20   0  128m  36m 3664 S 200.0  0.3  14:30.49 NetworkManager

26799 gse       20   0  389m  15m  12m S 200.0  0.1  23:21.10 vmtoolsd

1624 root      20   0  246m 9896  884 S 400.0  0.1   0:00.03 rsyslogd

2364 rtkit     21   1  164m 1136 1020 S 300.0  0.0   0:00.03 rtkit-daemon

21709 root      20   0  781m 6188 2696 S 800.0  0.1   0:00.02 avagent.bin

2086 qpidd     20   0  455m 2136 1764 S 600.0  0.0   0:00.00 qpidd

53686 gse       20   0 5361m 459m  11m S 4800.0  3.9   0:00.00 java

20029 gse       20   0 3859m 1.1g  13m S 5000.0  9.2   0:00.03 java

40456 gse       20   0 4764m 185m 9768 S 2400.0  1.6   0:00.01 java

36601 gse       20   0 4307m 1.9g 9088 S 4000.0 16.8   0:00.00 java

33680 gse       20   0 5791m 2.7g 9484 S 3900.0 23.5   0:00.02 java

33338 gse       20   0 5686m 1.6g 9296 S 6200.0 13.5   0:00.00 java

34215 gse       20   0 5686m 1.6g 9296 R 6200.0 13.5  11627:40 java

34163 gse       20   0 5791m 2.7g 9484 R 3900.0 23.5  11502:07 java

34221 gse       20   0 5686m 1.6g 9296 R 6200.0 13.5  11496:00 java

34155 gse       20   0 5791m 2.7g 9484 R 3900.0 23.5  11291:41 java

36687 gse       20   0 4307m 1.9g 9088 R 4000.0 16.8  10541:48 java

36679 gse       20   0 4307m 1.9g 9088 R 4000.0 16.8  10477:24 java

40474 gse       20   0 4764m 185m 9768 S 2400.0  1.6   3181:14 <file

20149 gse       20   0 3859m 1.1g  13m S 5000.0  9.2 455:20.60 java

20105 gse       20   0 3859m 1.1g  13m S 5000.0  9.2 429:22.28 java

40469 gse       20   0 4764m 185m 9768 S 2400.0  1.6 422:31.65 java

36660 gse       20   0 4307m 1.9g 9088 S 4000.0 16.8 278:48.14 java

33395 gse       20   0 5686m 1.6g 9296 S 6200.0 13.5 278:29.52 java

33737 gse       20   0 5791m 2.7g 9484 S 3900.0 23.5 276:57.92 java

36647 gse       20   0 4307m 1.9g 9088 S 4000.0 16.8 165:29.66 java

33384 gse       20   0 5686m 1.6g 9296 S 6200.0 13.5 141:00.07 java

40473 gse       20   0 4764m 185m 9768 S 2400.0  1.6 133:09.33 LogStash::Runne

40462 gse       20   0 4764m 185m 9768 S 2400.0  1.6 131:33.74 java

40457 gse       20   0 4764m 185m 9768 S 2400.0  1.6 130:39.84 LogStash::Runne

34235 gse       20   0 5686m 1.6g 9296 S 6200.0 13.5 124:40.17 java

33726 gse       20   0 5791m 2.7g 9484 S 3900.0 23.5 110:31.15 java

20100 gse       20   0 3859m 1.1g  13m S 5000.0  9.2 102:40.35 java

53732 gse       20   0 5361m 459m  11m S 4800.0  3.9  95:30.82 java

53699 gse       20   0 5361m 459m  11m S 4800.0  3.9  95:10.05 java

 

 

We randomly picked the TID’s from the above and searched in the thread dump of these services mentioned above – We found the thread that are consuming high CPU are pointing to play-scheduler  thread or play application-scheduler threads.

 

For 34215:

"play-scheduler-1" prio=10 tid=0x00007fd164026000 nid=0x85a7 runnable [0x00007fd1c1966000]

   java.lang.Thread.State: RUNNABLE

        at akka.dispatch.AbstractNodeQueue.pollNode(AbstractNodeQueue.java:85)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.executeBucket$1(Scheduler.scala:399)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.nextTick(Scheduler.scala:411)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.run(Scheduler.scala:363)

        at java.lang.Thread.run(Thread.java:679)

 

 

"application-scheduler-1" prio=10 tid=0x00007f27bc001800 nid=0x8573 runnable [0x00007f282bbfa000]

   java.lang.Thread.State: RUNNABLE

        at akka.dispatch.AbstractNodeQueue.pollNode(AbstractNodeQueue.java:85)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.executeBucket$1(Scheduler.scala:399)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.nextTick(Scheduler.scala:411)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.run(Scheduler.scala:363)

       at java.lang.Thread.run(Thread.java:679)

 

For 34155:

"play-scheduler-1" prio=10 tid=0x00007f27d001d800 nid=0x856b runnable [0x00007f28304c4000]

   java.lang.Thread.State: RUNNABLE

        at akka.dispatch.AbstractNodeQueue.pollNode(AbstractNodeQueue.java:85)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.executeBucket$1(Scheduler.scala:399)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.nextTick(Scheduler.scala:411)

        at akka.actor.LightArrayRevolverScheduler$$anon$12.run(Scheduler.scala:363)

        at java.lang.Thread.run(Thread.java:679)

Can you please help us to figure out the root cause for this issue from the Play perspective and resolve this issue?

Thanks in advance!

Thanks,

Mani

[赵光鹏]

I also encountered such a problem.

my playframework version is 2.3.8

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

在 2015年2月3日星期二 UTC+8下午2:02:41，Manikandan Kaliyaperumal写道：