Uploaded image for project: 'OpenDJ'
  1. OpenDJ
  2. OPENDJ-4598

Replication Server cursoring through obsolete replica ID's causing high CPU spin

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Blocker
    • Resolution: Fixed
    • Affects Version/s: 3.5.2
    • Fix Version/s: 6.0.0
    • Component/s: None
    • Labels:
    • Support Ticket IDs:
    • Sprint:
      OpenDJ Sprint 120

      Description

      This issue is hitting two distinct replication topologies:

      • Example 1: has 4 DS+RS's (4 current DSID's) 
      • Example 2: has 4 Standalone DS (4 current DSID's) with 2 Standalone RS's 

      Example 1:

      Suffix DN        : Server                    : Entries : Replication enabled : DS ID : RS ID : RS Port (1) : M.C. (2) : A.O.M.C. (3)                 : Security (4)
      -----------------:---------------------------:---------:---------------------:-------:-------:-------------:----------:------------------------------:-------------
      dc=example,dc=com : ldap1.example.com:4444    : 25926   : true                : 27770 : 20203 : 8989        : 0        : NA                           : false       
      dc=example,dc=com : ldap2.example.com:4444    : 25926   : true                : 32402 : 21058 : 8989        : 0        : NA                           : false       
      dc=example,dc=com : ldap3.example.com:4444    : 25926   : true                : 12313 : 14471 : 8989        : 0        : NA                           : false       
      dc=example,dc=com : ldap4.example.com:4444    : 25922   : true                : 29168 : 1854  : 8989        : 171      : Tue Apr 11 22                : false
      

      Stacks from each show an RS writing to another RS and cursoring through changelogDb files. 

      These stacks are the same and are observed to be the same on both example topologies.

      CPU = 99.9
      
      "Replication server RS(20203) writing to Replication server RS(1854) for domain "dc=example,dc=com" at ldap1.example.com/10.0.10.10:8989" #111 prio=5 os_prio=0 tid=0x0000000001c71800 nid=0x717d runnable [0x00007f5f6faf9000]
      
         java.lang.Thread.State: RUNNABLE
              at java.io.RandomAccessFile.length(Native Method)
              at java.io.RandomAccessFile.skipBytes(RandomAccessFile.java:468)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.readNextRecord(BlockLogReader.java:311)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.readRecord(BlockLogReader.java:244)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.searchClosestBlockStartToKey(BlockLogReader.java:399)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.seekToRecord(BlockLogReader.java:158)
              at org.opends.server.replication.server.changelog.file.LogFile$LogFileCursor.positionTo(LogFile.java:634)
              at org.opends.server.replication.server.changelog.file.Log$InternalLogCursor.positionTo(Log.java:1286)
              at org.opends.server.replication.server.changelog.file.Log$AbortableLogCursor.positionTo(Log.java:1537)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.nextWhenCursorIsExhaustedOrNotCorrectlyPositionned(FileReplicaDBCursor.java:117)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.next(FileReplicaDBCursor.java:111)
              at org.opends.server.replication.server.changelog.file.ReplicaCursor.next(ReplicaCursor.java:123)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.addCursor(CompositeDBCursor.java:170)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.recycleExhaustedCursors(CompositeDBCursor.java:126)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.next(CompositeDBCursor.java:107)
              at org.opends.server.replication.server.changelog.file.DomainDBCursor.next(DomainDBCursor.java:32)
              at org.opends.server.replication.server.MessageHandler.fillLateQueue(MessageHandler.java:399)
              at org.opends.server.replication.server.MessageHandler.getNextMessage(MessageHandler.java:273)
              at org.opends.server.replication.server.ServerHandler.take(ServerHandler.java:928)
              at org.opends.server.replication.server.ServerWriter.run(ServerWriter.java:94)
      
      CPU = 99.9
      
      "Replication server RS(20203) writing to Replication server RS(1854) for domain "dc=example,dc=com" at ldap1.example.com/10.0.10.10:8989" #111 prio=5 os_prio=0 tid=0x0000000001c71800 nid=0x717d runnable [0x00007f5f6faf9000]
      
         java.lang.Thread.State: RUNNABLE
              at java.io.RandomAccessFile.readBytes(Native Method)
              at java.io.RandomAccessFile.read(RandomAccessFile.java:377)
              at java.io.RandomAccessFile.readFully(RandomAccessFile.java:436)
              at java.io.RandomAccessFile.readFully(RandomAccessFile.java:416)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.positionToRecordFromBlockStart(BlockLogReader.java:269)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.readRecord(BlockLogReader.java:242)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.searchClosestBlockStartToKey(BlockLogReader.java:399)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.seekToRecord(BlockLogReader.java:158)
              at org.opends.server.replication.server.changelog.file.LogFile$LogFileCursor.positionTo(LogFile.java:634)
              at org.opends.server.replication.server.changelog.file.Log$InternalLogCursor.positionTo(Log.java:1286)
              at org.opends.server.replication.server.changelog.file.Log$AbortableLogCursor.positionTo(Log.java:1537)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.nextWhenCursorIsExhaustedOrNotCorrectlyPositionned(FileReplicaDBCursor.java:117)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.next(FileReplicaDBCursor.java:111)
              at org.opends.server.replication.server.changelog.file.ReplicaCursor.next(ReplicaCursor.java:123)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.addCursor(CompositeDBCursor.java:170)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.recycleExhaustedCursors(CompositeDBCursor.java:126)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.next(CompositeDBCursor.java:107)
              at org.opends.server.replication.server.changelog.file.DomainDBCursor.next(DomainDBCursor.java:32)
              at org.opends.server.replication.server.MessageHandler.fillLateQueue(MessageHandler.java:394)
              at org.opends.server.replication.server.MessageHandler.getNextMessage(MessageHandler.java:273)
              at org.opends.server.replication.server.ServerHandler.take(ServerHandler.java:928)
              at org.opends.server.replication.server.ServerWriter.run(ServerWriter.java:94)
      

      Example 2: The same stacks occur in this topology as well.
       

      Suffix DN          : Server              : Entries  : Replication enabled : DS ID : RS ID : RS Port (1) : M.C. (2) : A.O.M.C. (3)                 : Security (4)
      -------------------:---------------------:----------:---------------------:-------:-------:-------------:----------:------------------------------:-------------
      dc=example,dc=com  : 10.10.10.10:5444    : 0        : false               : :     : :     :             : 0        : NA                           : false*      
      dc=example,dc=com  : 10.10.10.11:4444    : 31       : false               : :     : :     :             : 0        : NA                           : false*      
      dc=example,dc=com  : 10.10.10.12:4444    : 29595868 : true                : 3667  : (5)   :             : 0        : NA                           : false*      
      dc=example,dc=com  : 10.10.10.13:4444    : 29595868 : true                : 796   : (5)   :             : 0        : NA                           : false*      
      dc=example,dc=com  : 10.10.10.14:4444    : 29595867 : true                : 20665 : (5)   :             : 0        : Sat Jul 29 06                : false*      
      dc=example,dc=com  : 10.10.10.15:4444    : 29595867 : true                : 10994 : (5)   :             : 0        : NA                           : false*      
                         : 10.10.10.16:5444    : (6)      : true                : dsid  : 28067 : 9898        : 0        : NA                           : false       
                         : 10.10.10.17:4444    : (6)      : true                : dsid  : 13029 : 8989        : 0        : NA                           : false
      

       
      Stacks for Example 2 are shown to be the same
       

      CPU = 99.9
      
      "Replication server RS(13029) writing to Replica DS(10994) for domain "dc=example,dc=com" at 10.10.10.17/10.10.10.17:46156" #135 prio=5 os_prio=0 tid=0x00007f3c1c020000 nid=0x796c runnable [0x00007f3c18070000]
      
         java.lang.Thread.State: RUNNABLE
              at java.io.RandomAccessFile.seek0(Native Method)
              at java.io.RandomAccessFile.seek(RandomAccessFile.java:557)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.positionToRecordFromBlockStart(BlockLogReader.java:265)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.readRecord(BlockLogReader.java:242)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.searchClosestBlockStartToKey(BlockLogReader.java:399)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.seekToRecord(BlockLogReader.java:158)
              at org.opends.server.replication.server.changelog.file.LogFile$LogFileCursor.positionTo(LogFile.java:634)
              at org.opends.server.replication.server.changelog.file.Log$InternalLogCursor.positionTo(Log.java:1286)
              at org.opends.server.replication.server.changelog.file.Log$AbortableLogCursor.positionTo(Log.java:1537)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.nextWhenCursorIsExhaustedOrNotCorrectlyPositionned(FileReplicaDBCursor.java:117)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.next(FileReplicaDBCursor.java:111)
              at org.opends.server.replication.server.changelog.file.ReplicaCursor.next(ReplicaCursor.java:123)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.addCursor(CompositeDBCursor.java:170)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.recycleExhaustedCursors(CompositeDBCursor.java:126)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.next(CompositeDBCursor.java:107)
              at org.opends.server.replication.server.changelog.file.DomainDBCursor.next(DomainDBCursor.java:32)
              at org.opends.server.replication.server.MessageHandler.fillLateQueue(MessageHandler.java:399)
              at org.opends.server.replication.server.MessageHandler.getNextMessage(MessageHandler.java:273)
              at org.opends.server.replication.server.ServerHandler.take(ServerHandler.java:928)
              at org.opends.server.replication.server.ServerWriter.run(ServerWriter.java:94)
      
      CPU = 99.9
      
      "Replication server RS(13029) writing to Replica DS(10994) for domain "dc=example,dc=com" at 10.10.10.17/10.10.10.17:46156" #135 prio=5 os_prio=0 tid=0x00007f3c1c020000 nid=0x796c runnable [0x00007f3c18070000]
      
         java.lang.Thread.State: RUNNABLE
              at java.io.RandomAccessFile.length(Native Method)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.readNextRecord(BlockLogReader.java:291)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.readRecord(BlockLogReader.java:244)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.searchClosestBlockStartToKey(BlockLogReader.java:399)
              at org.opends.server.replication.server.changelog.file.BlockLogReader.seekToRecord(BlockLogReader.java:158)
              at org.opends.server.replication.server.changelog.file.LogFile$LogFileCursor.positionTo(LogFile.java:634)
              at org.opends.server.replication.server.changelog.file.Log$InternalLogCursor.positionTo(Log.java:1286)
              at org.opends.server.replication.server.changelog.file.Log$AbortableLogCursor.positionTo(Log.java:1537)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.nextWhenCursorIsExhaustedOrNotCorrectlyPositionned(FileReplicaDBCursor.java:117)
              at org.opends.server.replication.server.changelog.file.FileReplicaDBCursor.next(FileReplicaDBCursor.java:111)
              at org.opends.server.replication.server.changelog.file.ReplicaCursor.next(ReplicaCursor.java:123)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.addCursor(CompositeDBCursor.java:170)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.recycleExhaustedCursors(CompositeDBCursor.java:126)
              at org.opends.server.replication.server.changelog.file.CompositeDBCursor.next(CompositeDBCursor.java:107)
              at org.opends.server.replication.server.changelog.file.DomainDBCursor.next(DomainDBCursor.java:32)
              at org.opends.server.replication.server.MessageHandler.fillLateQueue(MessageHandler.java:394)
              at org.opends.server.replication.server.MessageHandler.getNextMessage(MessageHandler.java:273)
              at org.opends.server.replication.server.ServerHandler.take(ServerHandler.java:928)
              at org.opends.server.replication.server.ServerWriter.run(ServerWriter.java:94)
      

      In addition to the stacks/cpu usage being the same on each topology, there is another similar data point shared between each.  Each has obsolete DSID.server data left over in the changelogDb.

      Example 1 has 16 obsolete DSID.server paths.
       

      opendj; changelog-171211-142609/$ ls -l | grep server | grep -vE '27770|32402|12313|29168' | sed "s/leetrujillo/opendj/" | sed "s/staff/opendj/"
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 1178.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 12511.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 12888.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 13107.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 1512.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 15777.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 16046.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 1751.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 18266.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 19426.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 19537.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 20811.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 23490.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 26656.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 28531.server
      drwx------@ 3 opendj  opendj   96 Dec 11 12:26 32404.server
      

       
      When decoded, these obsolete head.logs show old change data dating back to March.
       

      1178.server
      Skipping, head.log size 0
      
      12313.server
      head.log.txt Dec 4 2017 12:32:01.841       Mon Dec 11 2017 12:13:34.729
      
      12511.server
      head.log.txt                                                            
      
      12888.server
      head.log.txt Jun 12 2017 08:52:34.474      Fri Jun 16 2017 18:04:04.384
      
      13107.server
      head.log.txt May 28 2017 23:22:03.527      Fri Jun 16 2017 14:55:34.292
      
      1512.server
      Skipping, head.log size 0
      
      15777.server
      head.log.txt Mar 13 2017 07:40:08.962      Fri Mar 24 2017 23:52:54.536
      
      16046.server
      head.log.txt Jun 17 2017 01:18:06.048      Sat Jun 17 2017 01:18:06.048
      
      1751.server
      head.log.txt May 31 2017 07:25:04.411      Fri Jun 16 2017 17:28:42.172
      
      18266.server
      head.log.txt Mar 9 2017 11:42:11.594       Fri Mar 24 2017 23:19:32.337
      
      19426.server
      head.log.txt Jun 15 2017 15:00:05.554      Fri Jun 16 2017 22:02:36.463
      
      19537.server
      Skipping, head.log size 0
      
      20811.server
      head.log.txt Mar 15 2017 22:13:13.327      Fri Mar 24 2017 22:47:22.041
      
      23490.server
      head.log.txt Mar 25 2017 02:03:17.432      Tue Apr 11 2017 19:00:50.349
      
      26656.server
      head.log.txt Mar 24 2017 06:46:12.423      Fri Mar 24 2017 23:54:33.010
      
      28531.server
      Skipping, head.log size 0
      
      32402.server
      head.log.txt Dec 4 2017 07:38:03.065       Mon Dec 11 2017 12:12:05.114
      
      32404.server
      Skipping, head.log size 0
      

       
      Example 2: has 8 obsolete DSID.server paths.

      opendj; 02-changelog-171103-054910/$ ls -l | grep server | grep -vE '3667|796|20665|10994' | sed "s/leetrujillo/opendj/" | sed "s/staff/opendj/"
      drwx------   4 opendj  opendj   128 Dec 15 16:30 10750.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 11124.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 12837.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 14286.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 16219.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 28761.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 28915.server
      drwx------   4 opendj  opendj   128 Dec 15 16:30 3966.server
      

       
      This example has a much higher change load and many obsolete "rotated" head.log files dating back to July.

       

      10750.server
      head.log.txt Jul 27 2017 17:26:53.911      Thu Jul 27 2017 19:36:15.429
      
      11124.server
      head.log.txt Jul 26 2017 18:23:43.525      Wed Jul 26 2017 18:44:07.370
      
      12837.server
      head.log.txt Aug 1 2017 08:45:40.767       Tue Aug 1 2017 11:29:16.594 
      
      14286.server
      0000015dba26fec337ce0029c9d5_0000015dbabe89b837ce002a43b1.log.txt	Aug 6 2017 18:45:04.067       Sun Aug 6 2017 21:30:35.576 
      0000015dbabe89b837ce002a43b2_0000015dbc2bbdb837ce002abaf1.log.txt	Aug 6 2017 21:30:35.576       Mon Aug 7 2017 04:09:29.528 
      0000015dbc2bc01637ce002abaf2_0000015dbcd7642337ce002b31da.log.txt	Aug 7 2017 04:09:30.134       Mon Aug 7 2017 07:16:58.787 
      0000015dbcd764eb37ce002b31db_0000015dbd0e2aae37ce002bade7.log.txt	Aug 7 2017 07:16:58.987       Mon Aug 7 2017 08:16:48.558 
      0000015dbd0e2b6c37ce002bade8_0000015dbd3c108b37ce002c2574.log.txt	Aug 7 2017 08:16:48.748       Mon Aug 7 2017 09:06:56.523 
      0000015dbd3c108b37ce002c2575_0000015dbd6abbbc37ce002c980f.log.txt	Aug 7 2017 09:06:56.523       Mon Aug 7 2017 09:57:55.004 
      0000015dbd6abbbc37ce002c9810_0000015dbd9b3de437ce002d058f.log.txt	Aug 7 2017 09:57:55.004       Mon Aug 7 2017 10:50:54.052 
      0000015dbd9b3de437ce002d0590_0000015dbdd492e337ce002d8583.log.txt	Aug 7 2017 10:50:54.052       Mon Aug 7 2017 11:53:31.363 
      0000015dbdd492e337ce002d8584_0000015dbe03d5f237ce002df72d.log.txt	Aug 7 2017 11:53:31.363       Mon Aug 7 2017 12:45:08.722 
      0000015dbe03d5f437ce002df72e_0000015dbe3c401c37ce002e6afd.log.txt	Aug 7 2017 12:45:08.724       Mon Aug 7 2017 13:46:45.916 
      0000015dbe3c401c37ce002e6afe_0000015dbe71022537ce002ede18.log.txt	Aug 7 2017 13:46:45.916       Mon Aug 7 2017 14:44:23.461 
      0000015dbe7102ed37ce002ede19_0000015dbe8a108537ce002f4bf3.log.txt	Aug 7 2017 14:44:23.661       Mon Aug 7 2017 15:11:45.541 
      0000015dbe8a108537ce002f4bf4_0000015dbea4d14237ce002fb7f1.log.txt	Aug 7 2017 15:11:45.541       Mon Aug 7 2017 15:40:58.818 
      0000015dbea4d14237ce002fb7f2_0000015dbec54a1037ce00302063.log.txt	Aug 7 2017 15:40:58.818       Mon Aug 7 2017 16:16:26.896 
      0000015dbec54ad837ce00302064_0000015dbf372d0737ce00308c58.log.txt	Aug 7 2017 16:16:27.096       Mon Aug 7 2017 18:20:50.567 
      0000015dbf372dcf37ce00308c59_0000015dbfecb72037ce0030f8f5.log.txt	Aug 7 2017 18:20:50.767       Mon Aug 7 2017 21:39:07.936 
      0000015dbfecb72037ce0030f8f6_0000015dc286299737ce0031654b.log.txt	Aug 7 2017 21:39:07.936       Tue Aug 8 2017 09:45:58.679 
      0000015dc2862a5f37ce0031654c_0000015dc34f6dce37ce0031d884.log.txt	Aug 8 2017 09:45:58.879       Tue Aug 8 2017 13:25:48.878 
      head.log.txt Aug 8 2017 13:25:49.078       Tue Aug 8 2017 14:16:44.959 
      
      16219.server
      head.log.txt Jul 29 2017 12:12:16.026      Sat Jul 29 2017 12:48:46.045
      
      28761.server
      0000015dba14288f705900266193_0000015dba8909a670590026cdc5.log.txt	Aug 6 2017 18:24:29.583       Sun Aug 6 2017 20:32:09.382 
      0000015dba8909a670590026cdc6_0000015dbb5b03ac705900273e35.log.txt	Aug 6 2017 20:32:09.382       Mon Aug 7 2017 00:21:30.412 
      0000015dbb5b0474705900273e36_0000015dbc949f3a70590027b064.log.txt	Aug 7 2017 00:21:30.612       Mon Aug 7 2017 06:04:03.002 
      0000015dbc94a00270590027b065_0000015dbce5c0b9705900281f64.log.txt	Aug 7 2017 06:04:03.202       Mon Aug 7 2017 07:32:39.993 
      0000015dbce5c181705900281f65_0000015dbd0908f8705900288dc9.log.txt	Aug 7 2017 07:32:40.193       Mon Aug 7 2017 08:11:12.248 
      0000015dbd0908f8705900288dca_0000015dbd24dc6c70590028fbda.log.txt	Aug 7 2017 08:11:12.248       Mon Aug 7 2017 08:41:35.852 
      0000015dbd24dc6c70590028fbdb_0000015dbd4080ad705900296541.log.txt	Aug 7 2017 08:41:35.852       Mon Aug 7 2017 09:11:47.373 
      0000015dbd4080ad705900296542_0000015dbd5b814170590029d14c.log.txt	Aug 7 2017 09:11:47.373       Mon Aug 7 2017 09:41:16.993 
      0000015dbd5b814170590029d14d_0000015dbd777d287059002a39f3.log.txt	Aug 7 2017 09:41:16.993       Mon Aug 7 2017 10:11:50.952 
      0000015dbd777d287059002a39f4_0000015dbd97b4a57059002aa852.log.txt	Aug 7 2017 10:11:50.952       Mon Aug 7 2017 10:47:02.309 
      0000015dbd97b56e7059002aa853_0000015dbdb236f27059002b0f14.log.txt	Aug 7 2017 10:47:02.510       Mon Aug 7 2017 11:15:59.602 
      0000015dbdb236f27059002b0f15_0000015dbdce96f17059002b72a6.log.txt	Aug 7 2017 11:15:59.602       Mon Aug 7 2017 11:46:59.185 
      0000015dbdce96f17059002b72a7_0000015dbdf276097059002bdf43.log.txt	Aug 7 2017 11:46:59.185       Mon Aug 7 2017 12:26:10.057 
      0000015dbdf276097059002bdf44_0000015dbe1189717059002c4c3a.log.txt	Aug 7 2017 12:26:10.057       Mon Aug 7 2017 13:00:06.641 
      0000015dbe118a397059002c4c3b_0000015dbe32c9d17059002cb85e.log.txt	Aug 7 2017 13:00:06.841       Mon Aug 7 2017 13:36:25.809 
      0000015dbe32c9d17059002cb85f_0000015dbe5416a97059002d256a.log.txt	Aug 7 2017 13:36:25.809       Mon Aug 7 2017 14:12:48.169 
      0000015dbe5416a97059002d256b_0000015dbeb88f0a7059002d9a7b.log.txt	Aug 7 2017 14:12:48.169       Mon Aug 7 2017 16:02:32.586 
      0000015dbeb891637059002d9a7c_0000015dc2648c467059002e090d.log.txt	Aug 7 2017 16:02:33.187       Tue Aug 8 2017 09:09:15.718 
      0000015dc2648d0e7059002e090e_0000015dc37743567059002e772d.log.txt	Aug 8 2017 09:09:15.918       Tue Aug 8 2017 14:09:19.446 
      head.log.txt Aug 8 2017 14:09:19.846       Tue Aug 8 2017 14:16:45.214 
      
      28915.server
      head.log.txt Jul 25 2017 18:01:13.578      Tue Jul 25 2017 19:15:46.230
      
      3966.server
      head.log.txt Jul 28 2017 20:32:44.472      Fri Jul 28 2017 20:37:05.084
      

      Strace data from Example 1 shows this data is constantly being opened and read.

      opendj; strace/$ grep changelogDb ldap81p-strace.out | sed "s,/, ,g" | awk '{print $2 " " $7 " " $8 " " $9}' | grep -E '1178|12313|12511|12888|13107|1512|15777|16046|1751|18266|19426|19537|20811|23490|26656|28531|32402|32404' | head
      
      open(" 3.dom 32404.server offline.state.tmp",
      open(" 3.dom 1512.server offline.state.tmp",
      open(" 3.dom 1178.server offline.state.tmp",
      open(" 3.dom 19537.server offline.state.tmp",
      open(" 3.dom 28531.server offline.state.tmp",
      open(" 3.dom 18266.server offline.state.tmp",
      open(" 3.dom 26656.server offline.state.tmp",
      open(" 3.dom 20811.server offline.state.tmp",
      open(" 3.dom 15777.server offline.state.tmp",
      open(" 3.dom 23490.server offline.state.tmp",
      

      When I count the occurrences of opens on "In-Use changelogDB DSID's" files versus "Obsolete changelogDB DSID's" we see that the instance is not constantly opening any of the In-Use changelog files.

      Server ldap81p-strace.out
      
      Total In-Use changelogDB DSID's       0
      Total Obsolete changelogDB DSID's     1335
      
      Server ldap82p-strace.out
      
      Total In-Use changelogDB DSID's       0
      Total Obsolete changelogDB DSID's     1335
      
      Server ldap83p-strace.out
      
      Total In-Use changelogDB DSID's       0
      Total Obsolete changelogDB DSID's     1335
      
      Server ldap84p-strace.out
      
      Total In-Use changelogDB DSID's       0
      Total Obsolete changelogDB DSID's     1335
      

      The last common element between each of these two separate topologies is they are running on DJ 3.5.2 with the following fixes:

      OPENDJ-3931,OPENDJ-3507,OPENDJ-4115,OPENDJ-4212

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                matthew Matthew Swift
                Reporter:
                lee.trujillo Lee Trujillo
              • Votes:
                1 Vote for this issue
                Watchers:
                9 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: