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

Significant throughput degradation is seen with CRUD on managed users with roles

    XMLWordPrintable

    Details

      Description

      Previously in master, create managed users with roles test can pass with dispatch rate 200 users/second over 900 seconds period, now the create requests in the same test would timeout with dispatch rate 10 users/second over 900 seconds period after relationship refactoring PR 3268.
      IDM log has the following error:

      Nov 22, 2017 1:19:13 AM org.forgerock.openidm.managed.ManagedObjectSet performSyncAction
      WARNING: Failed executing onSync script on notifyUpdate role:sync
      org.forgerock.json.resource.InternalServerErrorException: org.forgerock.json.resource.InternalServerErrorException: /password: org.forgerock.json.crypto.JsonCryptoException: java.security.UnrecoverableKeyException: Given final block not properly padded
              at org.forgerock.json.resource.ResourceException.newResourceException(ResourceException.java:231)
              at org.forgerock.openidm.script.ScriptThrownException.toResourceException(ScriptThrownException.java:131)
              at org.forgerock.openidm.managed.ManagedObjectSet.execScript(ManagedObjectSet.java:389)
              at org.forgerock.openidm.managed.ManagedObjectSet.execScriptHook(ManagedObjectSet.java:343)
              at org.forgerock.openidm.managed.ManagedObjectSet.performSyncAction(ManagedObjectSet.java:1748)
              at org.forgerock.openidm.managed.ManagedObjectSet.handleSignalVertexUpdateFromEdge(ManagedObjectSet.java:1869)
              at org.forgerock.openidm.managed.EdgeToVertexActionHandler.edgeMutationVertexCommonActions(EdgeToVertexActionHandler.java:180)
              at org.forgerock.openidm.managed.EdgeToVertexActionHandler.edgeCreated(EdgeToVertexActionHandler.java:99)
              at org.forgerock.openidm.managed.EdgeToVertexActionHandler.handleActionRequest(EdgeToVertexActionHandler.java:60)
              at org.forgerock.openidm.managed.ManagedObjectSet.actionInstance(ManagedObjectSet.java:1350)
              at org.forgerock.json.resource.InterfaceCollectionInstance.handleAction(InterfaceCollectionInstance.java:26)
              at org.forgerock.json.resource.FilterChain$Cursor.handleAction(FilterChain.java:55)
              at org.forgerock.json.resource.Resources$CollectionInstanceIdContextFilter.filterAction(Resources.java:490)
              at org.forgerock.json.resource.FilterChain$Cursor.handleAction(FilterChain.java:53)
      ...
      Caused by: org.forgerock.openidm.script.ScriptThrownException: org.forgerock.json.resource.InternalServerErrorException: /password: org.forgerock.json.crypto.JsonCryptoException: java.security.UnrecoverableKeyException: Given final block not properly padded {code=500, reason=Internal Server Error, message=org.forgerock.json.resource.InternalServerErrorException: /password: org.forgerock.json.crypto.JsonCryptoException: java.security.UnrecoverableKeyException: Given final block not properly padded}
              at org.forgerock.openidm.script.javascript.RhinoScriptEngine$3.newScriptThrownException(RhinoScriptEngine.java:382)
              at org.forgerock.openidm.script.javascript.RhinoScript.eval(RhinoScript.java:293)
              at sun.reflect.GeneratedMethodAccessor95.invoke(Unknown Source)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:498)
              at org.forgerock.openidm.script.registry.ScriptRegistryImpl$LibraryRecord.invoke(ScriptRegistryImpl.java:539)
              at com.sun.proxy.$Proxy47.eval(Unknown Source)
              at org.forgerock.openidm.script.registry.ScriptRegistryImpl$ScriptImpl.eval(ScriptRegistryImpl.java:814)
              at org.forgerock.openidm.script.registry.ScriptRegistryImpl$ScriptImpl.eval(ScriptRegistryImpl.java:825)
              at org.forgerock.openidm.managed.ManagedObjectSet.execScript(ManagedObjectSet.java:386)
              ... 170 more
      

      and the JDBC connection pool is full all the time(a snapshot when requests timeout):

      show processlist;
      +-------+---------+--------------------+---------+---------+------+-------+------------------+
      | Id    | User    | Host               | db      | Command | Time | State | Info             |
      +-------+---------+--------------------+---------+---------+------+-------+------------------+
      | 37278 | openidm | 10.192.192.1:46682 | openidm | Sleep   |    0 |       | NULL             |
      | 37300 | openidm | 10.192.192.1:46770 | openidm | Sleep   |    0 |       | NULL             |
      | 37302 | openidm | 10.192.192.1:46778 | openidm | Sleep   |    0 |       | NULL             |
      | 37303 | openidm | 10.192.192.1:46782 | openidm | Sleep   |    0 |       | NULL             |
      | 37305 | openidm | 10.192.192.1:46790 | openidm | Sleep   |    0 |       | NULL             |
      | 37307 | openidm | 10.192.192.1:46798 | openidm | Sleep   |    0 |       | NULL             |
      | 37308 | openidm | 10.192.192.1:46802 | openidm | Sleep   |    0 |       | NULL             |
      | 37309 | openidm | 10.192.192.1:46806 | openidm | Sleep   |    0 |       | NULL             |
      | 37311 | openidm | 10.192.192.1:46814 | openidm | Sleep   |    0 |       | NULL             |
      | 37312 | openidm | 10.192.192.1:46818 | openidm | Sleep   |    0 |       | NULL             |
      | 37314 | openidm | 10.192.192.1:46826 | openidm | Sleep   |    0 |       | NULL             |
      | 37316 | openidm | 10.192.192.1:46834 | openidm | Sleep   |    0 |       | NULL             |
      | 37317 | openidm | 10.192.192.1:46838 | openidm | Sleep   |    0 |       | NULL             |
      | 37319 | openidm | 10.192.192.1:46846 | openidm | Sleep   |    0 |       | NULL             |
      | 37321 | openidm | 10.192.192.1:46854 | openidm | Sleep   |    0 |       | NULL             |
      | 37322 | openidm | 10.192.192.1:46858 | openidm | Sleep   |    0 |       | NULL             |
      | 37324 | openidm | 10.192.192.1:46866 | openidm | Sleep   |    0 |       | NULL             |
      | 37325 | openidm | 10.192.192.1:46870 | openidm | Sleep   |    0 |       | NULL             |
      | 37327 | openidm | 10.192.192.1:46878 | openidm | Sleep   |    0 |       | NULL             |
      | 37329 | openidm | 10.192.192.1:46886 | openidm | Sleep   |    0 |       | NULL             |
      | 37397 | openidm | 10.192.192.1:47978 | openidm | Sleep   |    0 |       | NULL             |
      | 37398 | openidm | 10.192.192.1:47982 | openidm | Sleep   |    0 |       | NULL             |
      | 37399 | openidm | 10.192.192.1:48310 | openidm | Sleep   |    0 |       | NULL             |
      | 37400 | openidm | 10.192.192.1:48324 | openidm | Sleep   |    0 |       | NULL             |
      | 37401 | openidm | 10.192.192.1:48332 | openidm | Sleep   |    0 |       | NULL             |
      | 37402 | openidm | 10.192.192.1:48348 | openidm | Sleep   |    0 |       | NULL             |
      | 37403 | openidm | 10.192.192.1:48362 | openidm | Sleep   |    0 |       | NULL             |
      | 37404 | openidm | 10.192.192.1:48372 | openidm | Sleep   |    0 |       | NULL             |
      | 37405 | openidm | 10.192.192.1:48390 | openidm | Sleep   |    0 |       | NULL             |
      | 37406 | openidm | 10.192.192.1:48398 | openidm | Sleep   |    0 |       | NULL             |
      | 37407 | openidm | 10.192.192.1:48402 | openidm | Sleep   |    0 |       | NULL             |
      | 37408 | openidm | 10.192.192.1:48424 | openidm | Sleep   |    0 |       | NULL             |
      | 37409 | openidm | 10.192.192.1:48428 | openidm | Sleep   |    0 |       | NULL             |
      | 37410 | openidm | 10.192.192.1:48432 | openidm | Sleep   |    0 |       | NULL             |
      | 37411 | openidm | 10.192.192.1:48450 | openidm | Sleep   |    0 |       | NULL             |
      | 37412 | openidm | 10.192.192.1:48454 | openidm | Sleep   |    0 |       | NULL             |
      | 37413 | openidm | 10.192.192.1:48458 | openidm | Sleep   |    0 |       | NULL             |
      | 37414 | openidm | 10.192.192.1:48468 | openidm | Sleep   |    0 |       | NULL             |
      | 37415 | openidm | 10.192.192.1:48472 | openidm | Sleep   |    0 |       | NULL             |
      | 37416 | openidm | 10.192.192.1:48476 | openidm | Sleep   |    0 |       | NULL             |
      | 37417 | openidm | 10.192.192.1:48480 | openidm | Sleep   |    0 |       | NULL             |
      | 37418 | openidm | 10.192.192.1:48486 | openidm | Sleep   |    0 |       | NULL             |
      | 37419 | openidm | 10.192.192.1:48498 | openidm | Sleep   |    0 |       | NULL             |
      | 37420 | openidm | 10.192.192.1:48502 | openidm | Sleep   |    0 |       | NULL             |
      | 37421 | openidm | 10.192.192.1:48508 | openidm | Sleep   |    0 |       | NULL             |
      | 37422 | openidm | 10.192.192.1:48512 | openidm | Sleep   |    0 |       | NULL             |
      | 37423 | openidm | 10.192.192.1:48578 | openidm | Sleep   |    0 |       | NULL             |
      | 37424 | openidm | 10.192.192.1:48590 | openidm | Sleep   |    0 |       | NULL             |
      | 37425 | openidm | 10.192.192.1:48596 | openidm | Sleep   |    0 |       | NULL             |
      | 37426 | openidm | 10.192.192.1:48600 | openidm | Sleep   |    0 |       | NULL             |
      | 37428 | root    | 10.192.192.1:54718 | openidm | Query   |    0 | NULL  | show processlist |
      +-------+---------+--------------------+---------+---------+------+-------+------------------+
      51 rows in set (0.00 sec)
      

      Attached are IDM log files and jstack threads dump. Also attached is a screenshot(Thanks to Jenny) from Java Mission Control which indicates threads are blocked by the call openConnection(URL).

      To reproduce using pyforge:
      configure config.cfg with proper parameters(e.g. num_users, duration and idm version and etc.) and run test:

      python -u run-pybot.py -c stress -i gatling -s idm.CrudManUsersWithRoles -t IDM_Managed_User_With_Roles_Create_Put  OpenIDM
      

      Observe test fails and Gatling log indicates requests timeout.

        Attachments

        1. default.jfc
          20 kB
        2. default.jfc
          20 kB
        3. jstack.out
          6.59 MB
        4. openidm.ManUsersWithRolesCreatePut_20171122-004942.out.gz
          729 kB
        5. openidm0.log.0
          4.28 MB
        6. Screen Shot 2017-11-21 at 4.36.58 PM.png
          Screen Shot 2017-11-21 at 4.36.58 PM.png
          1.15 MB

          Issue Links

            Activity

              People

              Assignee:
              dhogan Dirk Hogan
              Reporter:
              Tinghua.Xu Tinghua Xu
              QA Assignee:
              Tinghua Xu Tinghua Xu
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: