Uploaded image for project: 'OpenIDM'
  1. OpenIDM
  2. OPENIDM-8025

With Postgres as a repo, IDM may become unresponsive after certain loads of user creation

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Not a defect
    • Affects Version/s: OpenIDM 4.5.0
    • Fix Version/s: None
    • Component/s: Performance
    • Labels:
      None
    • Environment:
      OpenIDM: 4.5.0 2b8d258 @ Etorki (GNB Jenkins slave)

      Description

      With 300 users per second there were run consecutively CREATE PUT, READ, UPDATE, DELETE and CREATE POST simulations for 300 seconds each. There were noticed lots of TimoutExceptions (timeout after one minute without response) during the last one.

      Some errors appear in IDM logs:

      Apr 01, 2017 3:31:18 PM org.forgerock.http.servlet.HttpFrameworkServlet writeResponse
      SEVERE: Failed to write response
      org.eclipse.jetty.io.EofException
      	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:192)
      	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:408)
      	at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:302)
      	at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:129)
      	at org.eclipse.jetty.server.HttpConnection$SendCallback.process(HttpConnection.java:697)
      	at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:246)
      	at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:208)
      	at org.eclipse.jetty.server.HttpConnection.send(HttpConnection.java:471)
      	at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:763)
      	at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801)
      	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:147)
      	at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:140)
      	at org.eclipse.jetty.server.HttpOutput.flush(HttpOutput.java:242)
      .
      .
      

      Full OpenIDM logs attached and here is relevant part of access log:

      "_id","timestamp","eventName","transactionId","userId","trackingIds","server.ip","server.port","client.ip","client.port","request.protocol","request.operation","request.detail","http.request.secure","http.request.method","http.request.path","http.request.queryP
      "a7527465-badd-4028-b596-a9d1374e019b-4710247","2017-04-01T13:31:16.477Z","access","a7527465-badd-4028-b596-a9d1374e019b-4707651","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46608","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""314""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"SUCCESSFUL",,,"296","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710248","2017-04-01T13:31:16.477Z","access","a7527465-badd-4028-b596-a9d1374e019b-4707537","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46582","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""313""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""effectiveRoles onRetrieve script encountered exception""}","302","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710249","2017-04-01T13:31:16.477Z","access","a7527465-badd-4028-b596-a9d1374e019b-4709623","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46928","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""323""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""effectiveRoles onRetrieve script encountered exception""}","77","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710253","2017-04-01T13:31:16.486Z","access","a7527465-badd-4028-b596-a9d1374e019b-4710098","openidm-admin",,"172.16.204.4","8080","172.16.204.4","47002","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""312""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""effectiveRoles onRetrieve script encountered exception""}","27","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710254","2017-04-01T13:31:16.486Z","access","a7527465-badd-4028-b596-a9d1374e019b-4709300","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46876","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""313""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"SUCCESSFUL",,,"173","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710255","2017-04-01T13:31:16.487Z","access","a7527465-badd-4028-b596-a9d1374e019b-4710088","openidm-admin",,"172.16.204.4","8080","172.16.204.4","47000","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""307""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""effectiveRoles onRetrieve script encountered exception""}","29","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710256","2017-04-01T13:31:16.487Z","access","a7527465-badd-4028-b596-a9d1374e019b-4709736","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46950","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""304""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""Error: Module \""lib/lodash\"" not found.""}","13","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710257","2017-04-01T13:31:16.487Z","access","a7527465-badd-4028-b596-a9d1374e019b-4709762","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46948","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""315""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""effectiveRoles onRetrieve script encountered exception""}","64","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710258","2017-04-01T13:31:16.487Z","access","a7527465-badd-4028-b596-a9d1374e019b-4708951","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46822","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""313""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"FAILED","500","{""code"":500,""reason"":""Internal Server Error"",""message"":""effectiveRoles onRetrieve script encountered exception""}","101","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      "a7527465-badd-4028-b596-a9d1374e019b-4710259","2017-04-01T13:31:16.486Z","access","a7527465-badd-4028-b596-a9d1374e019b-4708039","openidm-admin",,"172.16.204.4","8080","172.16.204.4","46676","CREST","CREATE",,"false","POST","http://etorki.internal.forgerock.com:8080/openidm/managed/user","{""_action"":[""create""]}","{""Accept"":[""application/json""],""Connection"":[""close""],""Content-Length"":[""318""],""Content-Type"":[""application/json""],""Host"":[""etorki.internal.forgerock.com:8080""],""User-Agent"":[""Robot/Gatling""],""X-OpenIDM-Username"":[""openidm-admin""]}","{}",,"SUCCESSFUL",,,"644","MILLISECONDS","[""openidm-admin"",""openidm-authorized""]"
      

      There are no entries in activity log during the period of unresponsiveness (19 seconds). After that period, IDM is still busy with processing past requests.
      In this period of time, there was excessive use of file descriptors (see attached SVG image). Note that sockets trend is for all of CRUD-C tests (so the first parts of trend are low).

        Attachments

        1. IDM_logs.zip
          638 kB
        2. idmrestusers.csv.gz
          1.82 MB
        3. sockets.svg
          30 kB

          Issue Links

            Activity

              People

              Assignee:
              brmiller Brendan Miller
              Reporter:
              tomas.hejret Tomas Hejret
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: