[OPENDJ-4598] Replication Server cursoring through obsolete replica IDs causing high CPU spin Created: 18/Dec/17  Updated: 05/Nov/20  Resolved: 23/Mar/18

Status: Done
Project: OpenDJ
Component/s: None
Affects Version/s: 3.5.2
Fix Version/s: 6.0.0, 5.5.2

Type: Bug Priority: Blocker
Reporter: Lee Trujillo Assignee: Matthew Swift
Resolution: Fixed Votes: 1
Labels: release-notes

Issue Links:
Backport
is backported by OPENDJ-5322 Backport OPENDJ-4598: Replication Ser... Done
is backported by OPENDJ-4627 Backport OPENDJ-4598: Replication Ser... Done
Depends
depends on OPENDJ-1702 Replace MessageHandler lateQueue and ... Done
is required by OPENDJ-5617 Update DS 6 release notes to list add... Done
Duplicate
is duplicated by OPENDJ-3522 Idle replication change log consumes ... Done
Relates
relates to OPENDJ-3985 Provide a way to remove obsolete repl... Done
is related to OPENDJ-2518 File base change log simplification Done
is related to OPENDJ-4457 Avoid unnecessary reads in BlockLogRe... Done
Dev Assignee: Matthew Swift
Support Ticket IDs:
Backports: OPENDJ-4627 (6.0.0) OPENDJ-5322 (5.5.2)

 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



 Comments   
Comment by Jean-Noël Rouvignac [ 09/Jan/18 ]

Note that this a lot less of a problem on 5.5.0 since we have fixed OPENDJ-1702.

OPENDJ-1702 removed the lateQueue and msgQueue preventing a constant opening and closing of the cursors on the DB.

Now, the cursors are opened once and never closed, thus we never need to read several times the same files.

Comment by Jean-Noël Rouvignac [ 12/Mar/18 ]

Should we read the last CSN in the file to quickly rule out such files if need be?

Comment by Lee Trujillo [ 13/Mar/18 ]

Jean-Noël Rouvignac we maintain a list of active ReplicaID's right? So I would think this idea would work.  Perhaps read them on a timed basis (every 24 hours or less?) or when we get a certain task such as dsreplication configure/unconfigure ?

Comment by Matthew Swift [ 16/Mar/18 ]

I think I have found the cause of this while investigating OPENDJ-4590 - see the final stack trace.

Once a replica stops publishing changes its replica DB becomes stable. All open cursors reach the head of the log and become "exhausted". All subsequent attempts to use cursors cause the exhausted cursors to be recycled triggering a very expensive binary searach + seek operation.

Hopefully the fix is as straightforward as the cause.

Comment by Matthew Swift [ 23/Mar/18 ]

I had to perform some refactoring work in order to fully understand the behavior of the FileReplicaDBCursor.

It should relatively straightforward to backport the fix by adapting the first and third commits (the second commit which merges the strategies can be avoided).

Comment by Christophe Sovant [ 13/Jun/18 ]

NOTE:
How to reproduce this issue:

  • configure replication between 4 servers
  • perfom modrate on all replicas
  • do unconfigure/configure replication in a loop
Comment by Matthew Swift [ 07/Nov/19 ]

Moved to closed state because the fixVersion has already been released.

Generated at Sun Nov 29 20:09:08 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.