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

Creating managed users with roles requests start timeout after a short period time

    Details

      Description

      We preload managed users with roles in a constant dispatch rate 50 users/second, we used to be able to do that at least 1900 seconds, now the requests start timeout after about 1500 seconds(25 minutes). The Gatling response looks like this:

      For DS as external repo:

       ---- Global Information --------------------------------------------------------
      > request count                                      95000 (OK=76972  KO=18028 )
      > min response time                                    112 (OK=112    KO=60000 )
      > max response time                                  60137 (OK=60016  KO=60137 )
      > mean response time                                 19179 (OK=9617   KO=60002 )
      > std deviation                                      24350 (OK=15812  KO=9     )
      > response time 50th percentile                       3298 (OK=317    KO=60001 )
      > response time 95th percentile                      60001 (OK=47786  KO=60003 )
      > response time 99th percentile                      60003 (OK=57806  KO=60057 )
      > response time 99.9th percentile                    60075 (OK=59501  KO=60109 )
      > mean requests/sec                                 48.445 (OK=39.251 KO=9.193 )
      ---- Response Time Distribution ------------------------------------------------
      > t < 800 ms                                         45693 ( 48%)
      > 800 ms < t < 1200 ms                                  82 (  0%)
      > t > 1200 ms                                        31197 ( 33%)
      > failed                                             18028 ( 19%)
      ---- Errors --------------------------------------------------------------------
      > i.g.h.c.i.RequestTimeoutException: Request timeout to picodon.  18028 (100.0%)
      internal.forgerock.com/172.16.204.143:8080 after 60000 ms
       ---- Global Information --------------------------------------------------------
      > request count                                      95000 (OK=95000  KO=0     )
      > min response time                                     94 (OK=94     KO=-     )
      > max response time                                   3595 (OK=3595   KO=-     )
      > mean response time                                   149 (OK=149    KO=-     )
      > std deviation                                        191 (OK=191    KO=-     )
      > response time 50th percentile                        131 (OK=131    KO=-     )
      > response time 95th percentile                        168 (OK=168    KO=-     )
      > response time 99th percentile                        207 (OK=207    KO=-     )
      > response time 99.9th percentile                     3008 (OK=3008   KO=-     )
      > mean requests/sec                                 49.974 (OK=49.974 KO=-     )
      ---- Response Time Distribution ------------------------------------------------
      > t < 800 ms                                         94240 ( 99%)
      > 800 ms < t < 1200 ms                                 122 (  0%)
      > t > 1200 ms                                          638 (  1%)
      > failed                                                 0 (  0%)

       

      When looked the IDM thread dumps, lots of IDM threads are calling Object.wait() in waiting states:

      grep qtp idm.stack |more
      "qtp427051914-136" #136 prio=5 os_prio=0 cpu=31106.17ms elapsed=1979.64s tid=0x00000000026e3000 nid=0x2af01 in Object.wait()  [0x00007f43a0cd5000]
      "qtp427051914-137" #137 prio=5 os_prio=0 cpu=37527.21ms elapsed=1979.64s tid=0x00000000026e5000 nid=0x2af02 in Object.wait()  [0x00007f43a0bd5000]
      "qtp427051914-139" #139 prio=5 os_prio=0 cpu=50197.92ms elapsed=1979.64s tid=0x00000000026e8800 nid=0x2af04 in Object.wait()  [0x00007f43a09d3000]
      "qtp427051914-140" #140 prio=5 os_prio=0 cpu=96781.55ms elapsed=1979.64s tid=0x00000000026ea800 nid=0x2af05 in Object.wait()  [0x00007f43a08d1000]
      "qtp427051914-141" #141 prio=5 os_prio=0 cpu=29519.23ms elapsed=1979.64s tid=0x00000000026ec800 nid=0x2af06 in Object.wait()  [0x00007f43a07d0000]
      "qtp427051914-143" #143 prio=5 os_prio=0 cpu=30425.55ms elapsed=1979.64s tid=0x00000000026f0000 nid=0x2af08 in Object.wait()  [0x00007f43a05cf000]
      "qtp427051914-145-acceptor-0@44840149-0.0.0.0:8080@25ac36ed{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}" #145 prio=3 os_prio=0 cpu=3801.38ms elapsed=1979.53s tid=0x0000000002731800 
      nid=0x2af0a runnable  [0x00007f43a01d0000]
      "qtp427051914-146-acceptor-1@59e39cf8-0.0.0.0:8080@25ac36ed{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}" #146 prio=3 os_prio=0 cpu=3769.96ms elapsed=1979.53s tid=0x0000000002732800 
      nid=0x2af0b waiting on condition  [0x00007f432bffe000]
      "qtp427051914-147" #147 prio=5 os_prio=0 cpu=0.13ms elapsed=1978.88s tid=0x0000000002477000 nid=0x2af0c runnable  [0x00007f43a13dc000]
      "qtp427051914-148" #148 prio=5 os_prio=0 cpu=0.09ms elapsed=1978.88s tid=0x0000000002772000 nid=0x2af0d runnable  [0x00007f432bcfd000]
      "qtp427051914-149" #149 prio=5 os_prio=0 cpu=0.08ms elapsed=1978.88s tid=0x0000000002776800 nid=0x2af0e runnable  [0x00007f432bbfc000]
      "qtp427051914-150" #150 prio=5 os_prio=0 cpu=0.09ms elapsed=1978.88s tid=0x000000000277b000 nid=0x2af0f runnable  [0x00007f432bafb000]
      "qtp427051914-151" #151 prio=5 os_prio=0 cpu=0.08ms elapsed=1978.88s tid=0x0000000002780000 nid=0x2af10 runnable  [0x00007f432b9fa000]
      "qtp427051914-152" #152 prio=5 os_prio=0 cpu=0.08ms elapsed=1978.88s tid=0x0000000002784800 nid=0x2af11 runnable  [0x00007f432b8f9000]
      "qtp427051914-153" #153 prio=5 os_prio=0 cpu=0.08ms elapsed=1978.88s tid=0x0000000002789800 nid=0x2af12 runnable  [0x00007f432b7f8000]
      "qtp427051914-154" #154 prio=5 os_prio=0 cpu=0.09ms elapsed=1978.88s tid=0x000000000278e000 nid=0x2af13 runnable  [0x00007f432b6f7000]
      "qtp427051914-155-acceptor-0@33d58961-0.0.0.0:8443@4d55caa5{SSL,[ssl, http/1.1]}{0.0.0.0:8443}" #155 prio=3 os_prio=0 cpu=0.15ms elapsed=1978.88s tid=0x0000000002790000 nid
      =0x2af14 runnable  [0x00007f432b5f6000]
      "qtp427051914-156-acceptor-1@19fc8a12-0.0.0.0:8443@4d55caa5{SSL,[ssl, http/1.1]}{0.0.0.0:8443}" #156 prio=3 os_prio=0 cpu=0.15ms elapsed=1978.88s tid=0x0000000002792000 nid
      =0x2af15 waiting on condition  [0x00007f432b4f5000]
      "qtp427051914-158" #158 prio=5 os_prio=0 cpu=0.16ms elapsed=1978.33s tid=0x0000000002797800 nid=0x2af18 runnable  [0x00007f44e3afd000]
      "qtp427051914-159" #159 prio=5 os_prio=0 cpu=0.09ms elapsed=1978.33s tid=0x000000000279b800 nid=0x2af19 runnable  [0x00007f44e334c000]
      "qtp427051914-160" #160 prio=5 os_prio=0 cpu=0.10ms elapsed=1978.33s tid=0x00000000027a0000 nid=0x2af1a runnable  [0x00007f43a16df000]
      "qtp427051914-161" #161 prio=5 os_prio=0 cpu=0.12ms elapsed=1978.33s tid=0x00000000027a4000 nid=0x2af1b runnable  [0x00007f44e324b000]
      "qtp427051914-162" #162 prio=5 os_prio=0 cpu=0.18ms elapsed=1978.32s tid=0x00000000027a8000 nid=0x2af1c runnable  [0x00007f43a15de000]
      "qtp427051914-163" #163 prio=5 os_prio=0 cpu=0.10ms elapsed=1978.32s tid=0x00000000027ac000 nid=0x2af1d runnable  [0x00007f43a14dd000]
      "qtp427051914-164" #164 prio=5 os_prio=0 cpu=0.10ms elapsed=1978.32s tid=0x00000000027b0800 nid=0x2af1e runnable  [0x00007f432b2f3000]
      "qtp427051914-165" #165 prio=5 os_prio=0 cpu=0.08ms elapsed=1978.32s tid=0x00000000027b5000 nid=0x2af1f runnable  [0x00007f432b1f2000]
      "qtp427051914-166-acceptor-0@701944b-0.0.0.0:8444@69a06831{SSL,[ssl, http/1.1]}{0.0.0.0:8444}" #166 prio=3 os_prio=0 cpu=0.18ms elapsed=1978.32s tid=0x00000000027b7000 nid=
      0x2af20 runnable  [0x00007f432b0f1000]
      "qtp427051914-167-acceptor-1@3830a89c-0.0.0.0:8444@69a06831{SSL,[ssl, http/1.1]}{0.0.0.0:8444}" #167 prio=3 os_prio=0 cpu=0.16ms elapsed=1978.32s tid=0x00000000027b9000 nid
      =0x2af21 waiting on condition  [0x00007f432aff0000]
      "qtp427051914-209" #209 prio=5 os_prio=0 cpu=92049.46ms elapsed=1971.30s tid=0x00007f4344003000 nid=0x2af61 in Object.wait()  [0x00007f432aeeb000]
      "qtp427051914-213" #213 prio=5 os_prio=0 cpu=207650.13ms elapsed=1970.92s tid=0x00007f434400b800 nid=0x2af6c in Object.wait()  [0x00007f43223ea000]
      "qtp427051914-218" #218 prio=5 os_prio=0 cpu=23372.32ms elapsed=1846.40s tid=0x00007f44bc009800 nid=0x2b077 in Object.wait()  [0x00007f43a06cf000]
      "qtp427051914-219" #219 prio=5 os_prio=0 cpu=28809.09ms elapsed=1846.40s tid=0x00007f4344004800 nid=0x2b078 in Object.wait()  [0x00007f43222e9000]
      "qtp427051914-223" #223 prio=5 os_prio=0 cpu=29222.17ms elapsed=1846.37s tid=0x00007f4350008800 nid=0x2b07d in Object.wait()  [0x00007f44e263d000]
      "qtp427051914-224" #224 prio=5 os_prio=0 cpu=25764.42ms elapsed=1846.36s tid=0x00007f434c1c6000 nid=0x2b07f runnable  [0x00007f44e2742000]
      "qtp427051914-225" #225 prio=5 os_prio=0 cpu=24553.74ms elapsed=1846.34s tid=0x00007f435800f000 nid=0x2b081 waiting on condition  [0x00007f44e354e000]
      "qtp427051914-226" #226 prio=5 os_prio=0 cpu=29664.22ms elapsed=1846.32s tid=0x00007f4354007800 nid=0x2b086 runnable  [0x00007f44e2d45000]
      "qtp427051914-227" #227 prio=5 os_prio=0 cpu=68051.16ms elapsed=1846.30s tid=0x00007f435c009800 nid=0x2b089 in Object.wait()  [0x00007f44e2c43000]
      "qtp427051914-228" #228 prio=5 os_prio=0 cpu=26990.00ms elapsed=1846.28s tid=0x00007f4494001000 nid=0x2b08c in Object.wait()  [0x00007f44e233a000]
      "qtp427051914-229" #229 prio=5 os_prio=0 cpu=230136.11ms elapsed=1846.26s tid=0x00007f44bc00a800 nid=0x2b08e in Object.wait()  [0x00007f44e2b43000]
      "qtp427051914-230" #230 prio=5 os_prio=0 cpu=22682.41ms elapsed=1846.24s tid=0x00007f434800f800 nid=0x2b090 in Object.wait()  [0x00007f44e2a42000]
      "qtp427051914-231" #231 prio=5 os_prio=0 cpu=61209.66ms elapsed=1846.22s tid=0x00007f449c003000 nid=0x2b094 in Object.wait()  [0x00007f44e364c000]
      "qtp427051914-233" #233 prio=5 os_prio=0 cpu=27264.96ms elapsed=1846.20s tid=0x00007f44a4001000 nid=0x2b097 in Object.wait()  [0x00007f443a5eb000]
      "qtp427051914-235" #235 prio=5 os_prio=0 cpu=24095.25ms elapsed=1846.18s tid=0x00007f44cc001800 nid=0x2b09a in Object.wait()  [0x00007f43226ed000]
      "qtp427051914-237" #237 prio=5 os_prio=0 cpu=26391.45ms elapsed=1846.14s tid=0x00007f44d4520800 nid=0x2b09e waiting on condition  [0x00007f43225f0000]
      "qtp427051914-239" #239 prio=5 os_prio=0 cpu=33296.14ms elapsed=1846.12s tid=0x00007f44dc032800 nid=0x2b0a1 in Object.wait()  [0x00007f4321ee7000]
      "qtp427051914-240" #240 prio=5 os_prio=0 cpu=27986.53ms elapsed=1846.10s tid=0x00007f44e442e800 nid=0x2b0a3 in Object.wait()  [0x00007f43218e5000]
      "qtp427051914-241" #241 prio=5 os_prio=0 cpu=174076.17ms elapsed=1846.08s tid=0x00007f44f0001000 nid=0x2b0a7 in Object.wait()  [0x00007f43217e4000]
      "qtp427051914-242" #242 prio=5 os_prio=0 cpu=94456.04ms elapsed=1846.07s tid=0x00007f44ec001000 nid=0x2b0a9 in Object.wait()  [0x00007f43216e3000]
      "qtp427051914-247" #247 prio=5 os_prio=0 cpu=90225.04ms elapsed=1846.03s tid=0x00007f44f435d000 nid=0x2b0b0 runnable  [0x00007f43211e2000]
      "qtp427051914-248" #248 prio=5 os_prio=0 cpu=24255.97ms elapsed=1846.03s tid=0x00007f44fc14f000 nid=0x2b0b2 in Object.wait()  [0x00007f43210de000]
      "qtp427051914-249" #249 prio=5 os_prio=0 cpu=26262.70ms elapsed=1846.02s tid=0x00007f44fc150000 nid=0x2b0b3 in Object.wait()  [0x00007f4320fdd000]
      "qtp427051914-250" #250 prio=5 os_prio=0 cpu=115300.84ms elapsed=1846.01s tid=0x00007f4504001000 nid=0x2b0b5 in Object.wait()  [0x00007f4320edb000]
      "qtp427051914-251" #251 prio=5 os_prio=0 cpu=219933.75ms elapsed=1845.97s tid=0x00007f450c00b800 nid=0x2b0b9 in Object.wait()  [0x00007f4320cd9000]
      "qtp427051914-254" #254 prio=5 os_prio=0 cpu=28335.85ms elapsed=1845.95s tid=0x00007f4514001000 nid=0x2b0bd in Object.wait()  [0x00007f43209d5000]
      "qtp427051914-255" #255 prio=5 os_prio=0 cpu=34560.36ms elapsed=1845.95s tid=0x00007f4514003000 nid=0x2b0be in Object.wait()  [0x00007f43208d5000]
      "qtp427051914-256" #256 prio=5 os_prio=0 cpu=28370.80ms elapsed=1845.91s tid=0x00007f4528031000 nid=0x2b0c1 in Object.wait()  [0x00007f43207d4000]
      "qtp427051914-257" #257 prio=5 os_prio=0 cpu=23408.18ms elapsed=1845.89s tid=0x00007f4524004000 nid=0x2b0c3 in Object.wait()  [0x00007f43206d4000]
      "qtp427051914-258" #258 prio=5 os_prio=0 cpu=27046.65ms elapsed=1845.86s tid=0x00007f44fc152800 nid=0x2b0c5 in Object.wait()  [0x00007f43205d2000]
      "qtp427051914-259" #259 prio=5 os_prio=0 cpu=28578.62ms elapsed=1845.85s tid=0x00007f432c003800 nid=0x2b0c7 in Object.wait()  [0x00007f43204d1000]
      "qtp427051914-261" #261 prio=5 os_prio=0 cpu=61230.58ms elapsed=1845.80s tid=0x00007f4334012800 nid=0x2b0cb in Object.wait()  [0x00007f43202cf000]
      "qtp427051914-263" #263 prio=5 os_prio=0 cpu=23025.69ms elapsed=1845.79s tid=0x00007f433c005800 nid=0x2b0cd runnable  [0x00007f43200d1000]
      "qtp427051914-264" #264 prio=5 os_prio=0 cpu=116202.51ms elapsed=1845.75s tid=0x00007f434c1c7800 nid=0x2b0ce in Object.wait()  [0x00007f431ffcc000]
      "qtp427051914-266" #266 prio=5 os_prio=0 cpu=28530.14ms elapsed=1845.71s tid=0x00007f435400a800 nid=0x2b0d1 in Object.wait()  [0x00007f431fcca000]
      "qtp427051914-267" #267 prio=5 os_prio=0 cpu=125350.35ms elapsed=1845.66s tid=0x00007f4360003000 nid=0x2b0d3 runnable  [0x00007f431fbc9000]
      "qtp427051914-268" #268 prio=5 os_prio=0 cpu=27003.28ms elapsed=1845.66s tid=0x00007f435c00e800 nid=0x2b0d4 in Object.wait()  [0x00007f431fac8000]
      "qtp427051914-269" #269 prio=5 os_prio=0 cpu=28589.99ms elapsed=1845.65s tid=0x00007f4368003800 nid=0x2b0d5 waiting on condition  [0x00007f431f9ca000]
      "qtp427051914-270" #270 prio=5 os_prio=0 cpu=45019.00ms elapsed=1845.64s tid=0x00007f435c00f800 nid=0x2b0d6 in Object.wait()  [0x00007f431f8c5000]
      "qtp427051914-271" #271 prio=5 os_prio=0 cpu=29120.64ms elapsed=1845.63s tid=0x00007f4368005000 nid=0x2b0d7 in Object.wait()  [0x00007f431f7c3000]
      "qtp427051914-272" #272 prio=5 os_prio=0 cpu=24310.05ms elapsed=1845.63s tid=0x00007f433c007800 nid=0x2b0d8 waiting on condition  [0x00007f431f6c7000]
      "qtp427051914-273" #273 prio=5 os_prio=0 cpu=138393.60ms elapsed=1845.58s tid=0x00007f4378001000 nid=0x2b0d9 waiting on condition  [0x00007f431f5c6000]
      "qtp427051914-276" #276 prio=5 os_prio=0 cpu=25506.70ms elapsed=1845.56s tid=0x00007f4380003800 nid=0x2b0df waiting on condition  [0x00007f431efc0000]
      "qtp427051914-278" #278 prio=5 os_prio=0 cpu=24862.99ms elapsed=1845.52s tid=0x00007f435c021800 nid=0x2b0e1 in Object.wait()  [0x00007f431edba000]
      "qtp427051914-285" #285 prio=5 os_prio=0 cpu=30774.32ms elapsed=1845.49s tid=0x00007f4368007000 nid=0x2b0e2 in Object.wait()  [0x00007f431ecb9000]
      "qtp427051914-289" #289 prio=5 os_prio=0 cpu=29132.93ms elapsed=1845.40s tid=0x00007f437c001800 nid=0x2b0e9 in Object.wait()  [0x00007f431e5b2000]
      "qtp427051914-286" #286 prio=5 os_prio=0 cpu=27839.20ms elapsed=1845.40s tid=0x00007f435c025000 nid=0x2b0ec in Object.wait()  [0x00007f431e2af000]
      "qtp427051914-290" #290 prio=5 os_prio=0 cpu=29659.76ms elapsed=1845.40s tid=0x00007f4384001800 nid=0x2b0ed waiting on condition  [0x00007f431e1b2000]
      "qtp427051914-291" #291 prio=5 os_prio=0 cpu=24882.03ms elapsed=1845.40s tid=0x00007f4384003800 nid=0x2b0ee in Object.wait()  [0x00007f431e0ae000]
      "qtp427051914-292" #292 prio=5 os_prio=0 cpu=64878.48ms elapsed=1845.39s tid=0x00007f439c001000 nid=0x2b0f0 in Object.wait()  [0x00007f431deab000]
      "qtp427051914-295" #295 prio=5 os_prio=0 cpu=22617.96ms elapsed=1845.36s tid=0x00007f43b4001000 nid=0x2b0f2 in Object.wait()  [0x00007f431dcaa000]
      "qtp427051914-303" #303 prio=5 os_prio=0 cpu=25021.08ms elapsed=1845.31s tid=0x00007f43c0e1a000 nid=0x2b0fa in Object.wait()  [0x00007f431d4a1000]
      "qtp427051914-304" #304 prio=5 os_prio=0 cpu=222685.34ms elapsed=1845.30s tid=0x00007f43dc003800 nid=0x2b0fb in Object.wait()  [0x00007f431d3a1000]
      "qtp427051914-305" #305 prio=5 os_prio=0 cpu=28502.83ms elapsed=1845.26s tid=0x00007f43f0009800 nid=0x2b0fc in Object.wait()  [0x00007f431d29f000]
      "qtp427051914-306" #306 prio=5 os_prio=0 cpu=26901.40ms elapsed=1845.24s tid=0x00007f4384007800 nid=0x2b0fd in Object.wait()  [0x00007f431d19e000]
      "qtp427051914-307" #307 prio=5 os_prio=0 cpu=120583.72ms elapsed=1845.24s tid=0x00007f43f80b8000 nid=0x2b0fe in Object.wait()  [0x00007f431d09d000]
      "qtp427051914-308" #308 prio=5 os_prio=0 cpu=26408.56ms elapsed=1845.20s tid=0x00007f43ec001800 nid=0x2b0ff in Object.wait()  [0x00007f431cf9c000]
      "qtp427051914-309" #309 prio=5 os_prio=0 cpu=29937.03ms elapsed=1845.18s tid=0x00007f43c0e1c000 nid=0x2b100 waiting on condition  [0x00007f431ce9f000]
      "qtp427051914-310" #310 prio=5 os_prio=0 cpu=29424.92ms elapsed=1845.16s tid=0x00007f440804f000 nid=0x2b101 in Object.wait()  [0x00007f431cd9b000]
      "qtp427051914-311" #311 prio=5 os_prio=0 cpu=27343.84ms elapsed=1845.14s tid=0x00007f43fc79b800 nid=0x2b102 waiting on condition  [0x00007f431cc9d000]
      "qtp427051914-312" #312 prio=5 os_prio=0 cpu=27064.16ms elapsed=1845.13s tid=0x00007f440805b000 nid=0x2b103 in Object.wait()  [0x00007f431cb97000]
      "qtp427051914-313" #313 prio=5 os_prio=0 cpu=100403.62ms elapsed=1845.12s tid=0x00007f43fc79c000 nid=0x2b104 in Object.wait()  [0x00007f431ca97000]
      "qtp427051914-314" #314 prio=5 os_prio=0 cpu=104465.04ms elapsed=1845.10s tid=0x00007f441c003800 nid=0x2b105 waiting on condition  [0x00007f431c99a000]
      "qtp427051914-315" #315 prio=5 os_prio=0 cpu=28043.80ms elapsed=1845.08s tid=0x00007f443000c800 nid=0x2b106 in Object.wait()  [0x00007f431c895000]
      "qtp427051914-316" #316 prio=5 os_prio=0 cpu=25194.01ms elapsed=1845.06s tid=0x00007f44240a9800 nid=0x2b107 in Object.wait()  [0x00007f431c795000]
      "qtp427051914-317" #317 prio=5 os_prio=0 cpu=30131.09ms elapsed=1845.04s tid=0x00007f43fc07a000 nid=0x2b108 in Object.wait()  [0x00007f431c694000]
      "qtp427051914-318" #318 prio=5 os_prio=0 cpu=30264.33ms elapsed=1845.02s tid=0x00007f4448005000 nid=0x2b109 in Object.wait()  [0x00007f431c593000]
      "qtp427051914-320" #320 prio=5 os_prio=0 cpu=30946.37ms elapsed=1844.84s tid=0x00007f4454014000 nid=0x2b10f in Object.wait()  [0x00007f431c391000]
      "qtp427051914-323" #323 prio=5 os_prio=0 cpu=29572.38ms elapsed=1844.80s tid=0x00007f4454015000 nid=0x2b111 in Object.wait()  [0x00007f431c18e000]
      "qtp427051914-322" #322 prio=5 os_prio=0 cpu=28018.89ms elapsed=1844.79s tid=0x00007f445800d000 nid=0x2b112 waiting on condition  [0x00007f4317ffe000]
      "qtp427051914-324" #324 prio=5 os_prio=0 cpu=152560.15ms elapsed=1844.77s tid=0x00007f445800f800 nid=0x2b113 in Object.wait()  [0x00007f4317ef9000]
      "qtp427051914-325" #325 prio=5 os_prio=0 cpu=25816.90ms elapsed=1844.76s tid=0x00007f44c800b000 nid=0x2b114 in Object.wait()  [0x00007f4317df8000]
      "qtp427051914-327" #327 prio=5 os_prio=0 cpu=29968.36ms elapsed=1844.75s tid=0x00007f4448008800 nid=0x2b115 in Object.wait()  [0x00007f4317cf8000]
      "qtp427051914-326" #326 prio=5 os_prio=0 cpu=24933.87ms elapsed=1844.74s tid=0x00007f444401f800 nid=0x2b116 in Object.wait()  [0x00007f4317bf6000]
      "qtp427051914-328" #328 prio=5 os_prio=0 cpu=26507.20ms elapsed=1844.72s tid=0x00007f4460013000 nid=0x2b117 waiting on condition  [0x00007f4317af9000]
      "qtp427051914-329" #329 prio=5 os_prio=0 cpu=38502.00ms elapsed=1844.69s tid=0x00007f445c007800 nid=0x2b118 in Object.wait()  [0x00007f43179f4000]
      "qtp427051914-330" #330 prio=5 os_prio=0 cpu=128193.54ms elapsed=1844.68s tid=0x00007f446400d000 nid=0x2b119 in Object.wait()  [0x00007f43178f3000]
      "qtp427051914-335" #335 prio=5 os_prio=0 cpu=28283.48ms elapsed=1844.64s tid=0x00007f447000e000 nid=0x2b11d in Object.wait()  [0x00007f43174ef000]
      "qtp427051914-334" #334 prio=5 os_prio=0 cpu=210045.79ms elapsed=1844.64s tid=0x00007f4444021000 nid=0x2b11e in Object.wait()  [0x00007f43173ed000]
      "qtp427051914-336" #336 prio=5 os_prio=0 cpu=31820.34ms elapsed=1844.61s tid=0x00007f447800a800 nid=0x2b11f runnable  [0x00007f43172f1000]
      "qtp427051914-337" #337 prio=5 os_prio=0 cpu=27065.17ms elapsed=1844.59s tid=0x00007f447c00f000 nid=0x2b120 in Object.wait()  [0x00007f43171ec000]
      "qtp427051914-338" #338 prio=5 os_prio=0 cpu=29843.34ms elapsed=1844.57s tid=0x00007f4490009000 nid=0x2b121 in Object.wait()  [0x00007f43170ea000]
      "qtp427051914-339" #339 prio=5 os_prio=0 cpu=177824.01ms elapsed=1844.53s tid=0x00007f44b0008800 nid=0x2b123 in Object.wait()  [0x00007f4316fea000]
      "qtp427051914-340" #340 prio=5 os_prio=0 cpu=27593.21ms elapsed=1844.53s tid=0x00007f44b4392800 nid=0x2b124 in Object.wait()  [0x00007f4316ee9000]
      "qtp427051914-341" #341 prio=5 os_prio=0 cpu=29513.18ms elapsed=1844.49s tid=0x00007f4484004800 nid=0x2b126 in Object.wait()  [0x00007f4316ce7000]
      "qtp427051914-343" #343 prio=5 os_prio=0 cpu=31789.82ms elapsed=1844.47s tid=0x00007f447c011000 nid=0x2b127 in Object.wait()  [0x00007f4316be6000]
      "qtp427051914-344" #344 prio=5 os_prio=0 cpu=29024.48ms elapsed=1844.47s tid=0x00007f4498010800 nid=0x2b128 in Object.wait()  [0x00007f4316ae5000]
      "qtp427051914-345" #345 prio=5 os_prio=0 cpu=29237.36ms elapsed=1844.45s tid=0x00007f435c031000 nid=0x2b129 in Object.wait()  [0x00007f43169e4000]
      "qtp427051914-346" #346 prio=5 os_prio=0 cpu=43457.71ms elapsed=1844.44s tid=0x00007f44a4004000 nid=0x2b12a in Object.wait()  [0x00007f43168e4000]
      "qtp427051914-347" #347 prio=5 os_prio=0 cpu=141241.31ms elapsed=1844.33s tid=0x00007f44ac010000 nid=0x2b12b in Object.wait()  [0x00007f43167e2000]
      "qtp427051914-348" #348 prio=5 os_prio=0 cpu=27714.89ms elapsed=1844.32s tid=0x00007f435c032800 nid=0x2b12c in Object.wait()  [0x00007f43166e1000]
      "qtp427051914-349" #349 prio=5 os_prio=0 cpu=29398.18ms elapsed=1844.30s tid=0x00007f44ad30b000 nid=0x2b12d in Object.wait()  [0x00007f43165e0000]
      "qtp427051914-350" #350 prio=5 os_prio=0 cpu=209196.11ms elapsed=1844.29s tid=0x00007f435c034000 nid=0x2b12e in Object.wait()  [0x00007f43164e0000]
      "qtp427051914-351" #351 prio=5 os_prio=0 cpu=170656.06ms elapsed=1844.27s tid=0x00007f44b8590000 nid=0x2b12f in Object.wait()  [0x00007f43163df000]
      "qtp427051914-352" #352 prio=5 os_prio=0 cpu=26797.17ms elapsed=1844.24s tid=0x00007f44d8036800 nid=0x2b130 in Object.wait()  [0x00007f43162dd000]
      "qtp427051914-353" #353 prio=5 os_prio=0 cpu=41919.01ms elapsed=1844.21s tid=0x00007f44c00cb800 nid=0x2b131 in Object.wait()  [0x00007f43161dc000]
      "qtp427051914-355" #355 prio=5 os_prio=0 cpu=23897.68ms elapsed=1844.19s tid=0x00007f4348021000 nid=0x2b132 in Object.wait()  [0x00007f43160db000]
      "qtp427051914-354" #354 prio=5 os_prio=0 cpu=26359.69ms elapsed=1844.18s tid=0x00007f44cc004800 nid=0x2b133 in Object.wait()  [0x00007f4315fda000]
      "qtp427051914-357" #357 prio=5 os_prio=0 cpu=25732.96ms elapsed=1844.14s tid=0x00007f44d44f2000 nid=0x2b135 in Object.wait()  [0x00007f4315dd8000]
      "qtp427051914-358" #358 prio=5 os_prio=0 cpu=26244.56ms elapsed=1844.08s tid=0x00007f4500001000 nid=0x2b136 in Object.wait()  [0x00007f4315cd8000]
      "qtp427051914-359" #359 prio=5 os_prio=0 cpu=42987.83ms elapsed=1844.06s tid=0x00007f44f0005000 nid=0x2b137 runnable  [0x00007f4315bda000]
      "qtp427051914-360" #360 prio=5 os_prio=0 cpu=25985.94ms elapsed=1844.05s tid=0x00007f4500003000 nid=0x2b138 in Object.wait()  [0x00007f4315ad5000]
      "qtp427051914-361" #361 prio=5 os_prio=0 cpu=27472.50ms elapsed=1844.04s tid=0x00007f44f0007000 nid=0x2b139 in Object.wait()  [0x00007f43159d4000]
      "qtp427051914-364" #364 prio=5 os_prio=0 cpu=52291.85ms elapsed=1843.95s tid=0x00007f44ec007800 nid=0x2b13b in Object.wait()  [0x00007f43157d2000]
      "qtp427051914-365" #365 prio=5 os_prio=0 cpu=28834.22ms elapsed=1843.95s tid=0x00007f44dc03e800 nid=0x2b13c in Object.wait()  [0x00007f43156d2000]
      "qtp427051914-363" #363 prio=5 os_prio=0 cpu=22682.60ms elapsed=1843.93s tid=0x00007f44f4133800 nid=0x2b13d in Object.wait()  [0x00007f43155d0000]
      "qtp427051914-366" #366 prio=5 os_prio=0 cpu=29489.63ms elapsed=1843.92s tid=0x00007f44ec00f000 nid=0x2b13e in Object.wait()  [0x00007f43154d0000]
      "qtp427051914-367" #367 prio=5 os_prio=0 cpu=204838.41ms elapsed=1843.90s tid=0x00007f44f0008800 nid=0x2b13f waiting on condition  [0x00007f43153d2000]
      "qtp427051914-368" #368 prio=5 os_prio=0 cpu=85892.51ms elapsed=1843.87s tid=0x00007f451000e000 nid=0x2b142 in Object.wait()  [0x00007f43152cd000]
      "qtp427051914-369" #369 prio=5 os_prio=0 cpu=73174.33ms elapsed=1843.84s tid=0x00007f4514007800 nid=0x2b143 in Object.wait()  [0x00007f43151cd000]
      "qtp427051914-370" #370 prio=5 os_prio=0 cpu=93662.99ms elapsed=1843.82s tid=0x00007f44a425a800 nid=0x2b144 in Object.wait()  [0x00007f43150cb000]
      "qtp427051914-371" #371 prio=5 os_prio=0 cpu=27049.88ms elapsed=1843.81s tid=0x00007f455960c800 nid=0x2b145 in Object.wait()  [0x00007f4314fca000]
      "qtp427051914-372" #372 prio=5 os_prio=0 cpu=29046.62ms elapsed=1843.78s tid=0x00007f44ec010800 nid=0x2b146 in Object.wait()  [0x00007f4314eca000]
      "qtp427051914-374" #374 prio=5 os_prio=0 cpu=30494.32ms elapsed=1843.73s tid=0x00007f452400c000 nid=0x2b14a in Object.wait()  [0x00007f4314bc6000]
      "qtp427051914-376" #376 prio=5 os_prio=0 cpu=26563.00ms elapsed=1843.73s tid=0x00007f453800e000 nid=0x2b14b in Object.wait()  [0x00007f4314ac5000]
      "qtp427051914-377" #377 prio=5 os_prio=0 cpu=97422.16ms elapsed=1843.71s tid=0x00007f4538015800 nid=0x2b14c in Object.wait()  [0x00007f43149c4000]
      "qtp427051914-378" #378 prio=5 os_prio=0 cpu=31432.88ms elapsed=1843.69s tid=0x0000000003794000 nid=0x2b14d in Object.wait()  [0x00007f43148c3000]
      "qtp427051914-379" #379 prio=5 os_prio=0 cpu=28906.36ms elapsed=1843.66s tid=0x00007f432400b800 nid=0x2b14e in Object.wait()  [0x00007f43147c2000]
      "qtp427051914-380" #380 prio=5 os_prio=0 cpu=165279.49ms elapsed=1843.66s tid=0x00007f432400e000 nid=0x2b14f runnable  [0x00007f43146c5000]
      "qtp427051914-382" #382 prio=5 os_prio=0 cpu=24720.82ms elapsed=1843.61s tid=0x00007f432c010000 nid=0x2b151 in Object.wait()  [0x00007f43144c0000]
      "qtp427051914-383" #383 prio=5 os_prio=0 cpu=28648.36ms elapsed=1843.59s tid=0x00007f4338048000 nid=0x2b152 in Object.wait()  [0x00007f43143bf000]
      "qtp427051914-384" #384 prio=5 os_prio=0 cpu=26677.24ms elapsed=1843.59s tid=0x00007f4344027000 nid=0x2b153 in Object.wait()  [0x00007f43142bd000]
      "qtp427051914-387" #387 prio=5 os_prio=0 cpu=27000.55ms elapsed=1843.53s tid=0x0000000003791800 nid=0x2b155 in Object.wait()  [0x00007f43140bb000]
      "qtp427051914-388" #388 prio=5 os_prio=0 cpu=29447.35ms elapsed=1843.53s tid=0x0000000003793000 nid=0x2b157 in Object.wait()  [0x00007f4313eba000]
      "qtp427051914-389" #389 prio=5 os_prio=0 cpu=27290.44ms elapsed=1843.50s tid=0x00007f44cc016800 nid=0x2b158 waiting on condition  [0x00007f4313dbc000]
      "qtp427051914-390" #390 prio=5 os_prio=0 cpu=30207.71ms elapsed=1843.48s tid=0x00007f435000c800 nid=0x2b159 in Object.wait()  [0x00007f4313cb7000]
      "qtp427051914-391" #391 prio=5 os_prio=0 cpu=33902.81ms elapsed=1843.47s tid=0x00007f434c03d000 nid=0x2b15a in Object.wait()  [0x00007f4313bb7000]
      "qtp427051914-404" #404 prio=5 os_prio=0 cpu=27479.91ms elapsed=1843.41s tid=0x00007f4344028000 nid=0x2b161 runnable  [0x00007f43134b3000]
      "qtp427051914-408" #408 prio=5 os_prio=0 cpu=50123.19ms elapsed=1843.35s tid=0x00007f4370034000 nid=0x2b168 in Object.wait()  [0x00007f4312da8000]
      "qtp427051914-407" #407 prio=5 os_prio=0 cpu=27226.44ms elapsed=1843.35s tid=0x00007f435c038000 nid=0x2b169 in Object.wait()  [0x00007f4312ca7000]
      "qtp427051914-406" #406 prio=5 os_prio=0 cpu=27729.72ms elapsed=1843.35s tid=0x00007f4368017000 nid=0x2b16a in Object.wait()  [0x00007f4312ba7000]
      "qtp427051914-405" #405 prio=5 os_prio=0 cpu=23495.89ms elapsed=1843.35s tid=0x00007f4344029800 nid=0x2b16b in Object.wait()  [0x00007f4312aa6000]
      "qtp427051914-409" #409 prio=5 os_prio=0 cpu=30769.04ms elapsed=1843.29s tid=0x00007f4374145800 nid=0x2b16c runnable  [0x00007f43129a5000]
      "qtp427051914-410" #410 prio=5 os_prio=0 cpu=27827.38ms elapsed=1843.29s tid=0x00007f4374148000 nid=0x2b16d in Object.wait()  [0x00007f43128a2000]
      "qtp427051914-411" #411 prio=5 os_prio=0 cpu=28967.20ms elapsed=1843.29s tid=0x00007f44dc021000 nid=0x2b16e in Object.wait()  [0x00007f43127a3000]
      "qtp427051914-412" #412 prio=5 os_prio=0 cpu=27769.52ms elapsed=1843.21s tid=0x00007f435c03a000 nid=0x2b16f in Object.wait()  [0x00007f43126a1000]
      "qtp427051914-414" #414 prio=5 os_prio=0 cpu=27753.17ms elapsed=1843.17s tid=0x00007f43bc051800 nid=0x2b171 in Object.wait()  [0x00007f431249f000]
      "qtp427051914-415" #415 prio=5 os_prio=0 cpu=28605.27ms elapsed=1843.15s tid=0x00007f43c4055800 nid=0x2b172 in Object.wait()  [0x00007f431239f000]
      "qtp427051914-416" #416 prio=5 os_prio=0 cpu=27881.79ms elapsed=1843.14s tid=0x00007f4504007000 nid=0x2b173 in Object.wait()  [0x00007f431229d000]
      "qtp427051914-418" #418 prio=5 os_prio=0 cpu=27497.10ms elapsed=1843.07s tid=0x00007f43d802b000 nid=0x2b175 waiting on condition  [0x00007f431209f000]
      "qtp427051914-419" #419 prio=5 os_prio=0 cpu=30820.97ms elapsed=1843.07s tid=0x00007f43d802d800 nid=0x2b176 in Object.wait()  [0x00007f4311f9b000]
      "qtp427051914-420" #420 prio=5 os_prio=0 cpu=26636.17ms elapsed=1843.05s tid=0x00007f43d04d3800 nid=0x2b177 in Object.wait()  [0x00007f4311e99000]
      "qtp427051914-421" #421 prio=5 os_prio=0 cpu=169407.64ms elapsed=1843.00s tid=0x00007f451c008800 nid=0x2b178 runnable  [0x00007f4311d97000]
      "qtp427051914-422" #422 prio=5 os_prio=0 cpu=63892.59ms elapsed=1842.99s tid=0x00007f43dc01b800 nid=0x2b17a in Object.wait()  [0x00007f4311c97000]
      "qtp427051914-423" #423 prio=5 os_prio=0 cpu=26748.19ms elapsed=1842.92s tid=0x00007f43f0016000 nid=0x2b17b in Object.wait()  [0x00007f4311b96000]
      "qtp427051914-424" #424 prio=5 os_prio=0 cpu=94708.97ms elapsed=1842.90s tid=0x00007f43f0018000 nid=0x2b17c in Object.wait()  [0x00007f4311a96000]
      "qtp427051914-425" #425 prio=5 os_prio=0 cpu=91024.50ms elapsed=1842.88s tid=0x00007f4408069800 nid=0x2b17d waiting on condition  [0x00007f4311998000]
      "qtp427051914-426" #426 prio=5 os_prio=0 cpu=27449.16ms elapsed=1842.84s tid=0x00007f44f000d000 nid=0x2b17e in Object.wait()  [0x00007f4311894000]
      "qtp427051914-427" #427 prio=5 os_prio=0 cpu=218890.52ms elapsed=1842.82s tid=0x00007f451c00a000 nid=0x2b17f in Object.wait()  [0x00007f4311792000]
      "qtp427051914-428" #428 prio=5 os_prio=0 cpu=28879.31ms elapsed=1842.82s tid=0x00007f451c00d000 nid=0x2b180 in Object.wait()  [0x00007f4311691000]
      "qtp427051914-429" #429 prio=5 os_prio=0 cpu=20759.29ms elapsed=1842.80s tid=0x00007f433804c800 nid=0x2b181 runnable  [0x00007f4311594000]
      "qtp427051914-430" #430 prio=5 os_prio=0 cpu=216382.80ms elapsed=1842.78s tid=0x00007f43fc07b000 nid=0x2b182 in Object.wait()  [0x00007f4311490000]
      "qtp427051914-431" #431 prio=5 os_prio=0 cpu=105745.76ms elapsed=1842.72s tid=0x00007f440806b000 nid=0x2b183 in Object.wait()  [0x00007f431138e000]
      "qtp427051914-432" #432 prio=5 os_prio=0 cpu=24423.47ms elapsed=1842.70s tid=0x00007f44144ce800 nid=0x2b184 in Object.wait()  [0x00007f431128d000]
      "qtp427051914-433" #433 prio=5 os_prio=0 cpu=29607.41ms elapsed=1842.68s tid=0x00007f4410009800 nid=0x2b185 in Object.wait()  [0x00007f431118b000]
      "qtp427051914-434" #434 prio=5 os_prio=0 cpu=23663.85ms elapsed=1842.68s tid=0x00007f441000c000 nid=0x2b186 in Object.wait()  [0x00007f431108b000]
      "qtp427051914-522" #522 prio=5 os_prio=0 cpu=27125.02ms elapsed=903.65s tid=0x00007f4338052000 nid=0x2b55a in Object.wait()  [0x00007f44e37f6000]
      "qtp427051914-523" #523 prio=5 os_prio=0 cpu=26640.82ms elapsed=903.45s tid=0x00007f4344049800 nid=0x2b55b in Object.wait()  [0x00007f44e2840000]
      "qtp427051914-524" #524 prio=5 os_prio=0 cpu=25772.85ms elapsed=903.24s tid=0x00007f4494004000 nid=0x2b55c in Object.wait()  [0x00007f44e253d000]
      "qtp427051914-527" #527 prio=5 os_prio=0 cpu=29255.56ms elapsed=903.22s tid=0x00007f44c8032800 nid=0x2b55e in Object.wait()  [0x00007f443abef000]
      "qtp427051914-530" #530 prio=5 os_prio=0 cpu=25710.35ms elapsed=903.20s tid=0x00007f4358010000 nid=0x2b560 in Object.wait()  [0x00007f43a17dc000]
      "qtp427051914-529" #529 prio=5 os_prio=0 cpu=28925.67ms elapsed=903.20s tid=0x00007f43f001a800 nid=0x2b561 in Object.wait()  [0x00007f43212df000]
      "qtp427051914-528" #528 prio=5 os_prio=0 cpu=28839.09ms elapsed=903.20s tid=0x00007f443c0bc000 nid=0x2b562 in Object.wait()  [0x00007f4320ddb000]
      "qtp427051914-531" #531 prio=5 os_prio=0 cpu=28011.63ms elapsed=903.04s tid=0x00007f44c8033800 nid=0x2b565 in Object.wait()  [0x00007f4320bd8000]
      "qtp427051914-532" #532 prio=5 os_prio=0 cpu=20937.26ms elapsed=903.04s tid=0x00007f44b0001800 nid=0x2b569 in Object.wait()  [0x00007f4320ad7000]
      "qtp427051914-533" #533 prio=5 os_prio=0 cpu=27946.67ms elapsed=901.90s tid=0x00007f446801e800 nid=0x2b56d in Object.wait()  [0x00007f431f4c2000]
      "qtp427051914-535" #535 prio=5 os_prio=0 cpu=27445.41ms elapsed=901.55s tid=0x00007f4388026800 nid=0x2b570 in Object.wait()  [0x00007f431ebb8000]
      "qtp427051914-536" #536 prio=5 os_prio=0 cpu=19983.53ms elapsed=900.77s tid=0x00007f442001c000 nid=0x2b571 in Object.wait()  [0x00007f431eab7000]
      "qtp427051914-537" #537 prio=5 os_prio=0 cpu=24554.03ms elapsed=900.56s tid=0x00007f434c03b800 nid=0x2b572 in Object.wait()  [0x00007f431e9b7000]
      "qtp427051914-538" #538 prio=5 os_prio=0 cpu=25569.13ms elapsed=900.54s tid=0x00007f438c003800 nid=0x2b573 in Object.wait()  [0x00007f431e7b4000]
      "qtp427051914-539" #539 prio=5 os_prio=0 cpu=23311.74ms elapsed=900.18s tid=0x00007f4480063000 nid=0x2b575 in Object.wait()  [0x00007f431dba9000]
      "qtp427051914-581" #581 prio=5 os_prio=0 cpu=23534.90ms elapsed=837.26s tid=0x00007f440402f800 nid=0x2b5d4 in Object.wait()  [0x00007f43201ce000] 

      Checked the Runnable threads, many of them are in select() call waiting for IO.

      We used can at least can handle requests in 1900 seconds(around middle of Feb. 2020) , now can't, I tried to chase back for the causing commit but failed, they all failed with the same symptom even with the later January commits and earlier DJ milestone  build. So not really sure what caused the test failure now, but it looks that something we should improve.

      attached are idm and dj thread dumps(in different test runs), I also collected idm heap dump can be sent upon requests.

       

        Attachments

        1. dj.jstack
          57 kB
        2. idm.jstack
          5.15 MB

          Issue Links

            Activity

              People

              • Assignee:
                jason Jason Lemay
                Reporter:
                Tinghua.Xu Tinghua.Xu
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: