This discussion is archived
1 Reply Latest reply: May 22, 2013 1:27 PM by Linda Lee RSS

Master VLSN is significantly behind replicas - clean logs not being deleted

743476 Newbie
Currently Being Moderated
We recently upgraded to 5.0.73. In the last few days we have been seeing log messages like this:

130522 16:29:42:985 WARNING [Victory] Replication prevents deletion of 512 files by Cleaner. Start file=0x19315 holds CBVLSN 333,066,353, end file=0x19571 holds end VLSN 333,083,859
130522 16:29:42:985 WARNING [Victory] Cleaner has 512 files not deleted because they are protected by replication

The total cache size is less than 1Gb yet we have 42Gb of files. At the moment we are running out of diskspace when the backup runs on the master and failing over every few hours.

We are using the backup helper and we have three nodes. I was surprised to see that the master seems to be behind the replicas but do the values below represent the last checkpoint? I see that the times are different too. I have checked and our clocks are in sync. We do not have a cleaner backlog.

Group: OurGroup
Electable Members:
   Node1 (192.168.151.138:5003, LocalCBVLSN:333,163,542 at:Wed May 22 18:30:07 CEST 2013)
   Node2 (192.168.151.135:5002, LocalCBVLSN:333,161,592 at:Wed May 22 18:27:49 CEST 2013)
   Node3 (master, 192.168.151.141:5004, LocalCBVLSN:333,150,110 at:Wed May 22 18:10:43 CEST 2013)

Monitor Members:
   Node2Monitor (192.168.151.138:5007)
   Node3Monitor (192.168.151.141:5008)
   Node1Monitor (192.168.151.135:5006)

Any idea what is going on please? Is it the backup that is holding up the replication stream? It's running on all three nodes.

Thanks
James
  • 1. Re: Master VLSN is significantly behind replicas - clean logs not being deleted
    Linda Lee Journeyer
    Currently Being Moderated
    James,

    Both replication (the need for the master to hold back enough of the replication stream to feed the replicas) and backup can inhibit log file deletion. When backup is at play, there is usually a different warning message which refers to both backup and replication as being possible inhibitors, so the primary suspect here is replication.

    You are on the right track to examine the CBVLSN values in the replication group metadata, and it is indeed surprising that the master seems to be behind. However, this can happen when there's been a series of failovers and changes in mastership. One major criteria for selecting a master is to ensure that it is the node with the most recent data, so the master should actually be ahead in general. However, the metadata has an in-memory cache, and the display lags the actual latest-CBVLSN values, so there may be an innocent explanation for that.

    To get a better idea of what's happening, you want to get:
    1) a more detailed look at the VLSN values in the group metadata
    2) a sense for the pattern of log file deletion
    3) a sense for what kind of failovers might be happening, how the HA group is handling the failover, and if the VLSN values match what is in the group metadata
    4) a sense for the distribution of VLSNs in the .jdb files for each node

    For #1, to get a more detailed look at the group's VLSN values, use both the DbGroupAdmin command that you previously used, and the unadvertised DbDumpGroup utility. The difference between the two is that the public utility, DbGroupAdmin, contacts the current master, and requests its copy of the group metadata. But the group metadata is actually replicated itself, and also lives on each node in the group. The unadvertised DbDumpGroup utility works on a single node, and peeks directly at the metadata stored on disk. We use this to look at the group metadata when the group is not running, or, as in this case, if we want to see precisely what a particular node thinks of the metadata. Here's how the commands look when I run it on a group of 3 nodes:

    #Get the group metadata from the current master in a running group
    java -jar build/lib/je.jar DbGroupAdmin -groupName UnitTestGroup -helperHosts localhost:5001 -dumpGroup

    # Get the group metadata from each member of the group, directly off their persistent copy
    java -jar build/lib/je.jar DbDumpGroup -h build/test/standalone/data/rep0
    java -jar build/lib/je.jar DbDumpGroup -h build/test/standalone/data/rep1
    java -jar build/lib/je.jar DbDumpGroup -h build/test/standalone/data/rep2

    You would want to run this in rapid succession, so that the output of each command refers to roughly the same point in time.

    For #2, to look at the pattern of log file deletion, I do this: grep WARNING <envHome>/je.info.*

    In a well running system, the number of log files that are prohibited from deletion do mount up, but then get cleared out at checkpoint related cycles. One generally sees messages that say
    Cleaner has N files not deleted because they are protected by replication.
    where N cycles through from 0 -> some value, and back to 0. If there's a point when the log files start building up, it can be instructive to look at that time, and see if anything related happened, like a backup.

    For #3, to look at the failover pattern, you can do this to each member of the group:

    grep -i master <envHome>/je.info*

    It gives you output like this, which tells you when mastership changed, and what VLSN the replica got to when it rejoined. It's a way of trying to figure out if the group metadata VLSN info is seriously lagging, and doesn't match what is really happening in the group.
    130522 16:16:49:527 INFO [Node1] Master changed to Node2
    130522 16:16:49:527 INFO [Node1] Replica loop started with master: Node2(2)
    130522 16:16:50:541 INFO [Node1] Replica loop started with master: Node2(2)
    130522 16:16:50:572 INFO [Node1] Election thread exited. Group master: Node2(2)
    130522 16:16:50:666 INFO [Node1] Replica initialization completed. Replica VLSN: 18,503,543 Heartbeat master commit VLSN: 18,503,543 VLSN delta: 0
    130522 16:17:44:272 INFO [Node1] Master changed to Node3
    130522 16:17:44:272 INFO [Node1] Replica loop started with master: Node3(3)
    130522 16:17:44:272 INFO [Node1] Election thread exited. Group master: Node3(3)
    130522 16:17:44:350 INFO [Node1] Replica initialization completed. Replica VLSN: 18,743,681 Heartbeat master commit VLSN: 18,743,681 VLSN delta: 0



    For #4, to get a feel for the distribution of VLSNs on disk, use this unadvertised command:

    java -jar build/lib/je.jar DbPrintLog -h build/test/standalone/data/rep1 -vd
    <DbPrintLog>
    file 0xcd6 numRepRecords = 1 firstVLSN = 14,438,596 lastVLSN = 14,438,596
    file 0xe45 numRepRecords = 4177 firstVLSN = 16,097,943 lastVLSN = 16,102,119
    file 0xe46 numRepRecords = 1670 firstVLSN = 16,102,120 lastVLSN = 16,103,789
    file 0xe47 numRepRecords = 2631 firstVLSN = 16,103,790 lastVLSN = 16,106,420
    file 0xe48 numRepRecords = 6811 firstVLSN = 16,106,421 lastVLSN = 16,113,231
    file 0xe49 numRepRecords = 3125 firstVLSN = 16,113,232 lastVLSN = 16,116,356
    file 0xe4a numRepRecords = 5556 firstVLSN = 16,116,357 lastVLSN = 16,121,912
    file 0xe4b numRepRecords = 6639 firstVLSN = 16,121,913 lastVLSN = 16,128,551
    file 0xe4c numRepRecords = 2721 firstVLSN = 16,128,552 lastVLSN = 16,131,272
    file 0xe4d numRepRecords = 4895 firstVLSN = 16,131,273 lastVLSN = 16,136,167
    file 0xe4e numRepRecords = 2383 firstVLSN = 16,136,168 lastVLSN = 16,138,550
    file 0xe4f numRepRecords = 6947 firstVLSN = 16,138,551 lastVLSN = 16,145,497
    file 0xe50 numRepRecords = 4238 firstVLSN = 16,145,498 lastVLSN = 16,149,735
    file 0xe51 numRepRecords = 4542 firstVLSN = 16,149,736 lastVLSN = 16,154,277
    file 0xe52 numRepRecords = 6232 firstVLSN = 16,154,278 lastVLSN = 16,160,509
    file 0xe53 numRepRecords = 1966 firstVLSN = 16,160,510 lastVLSN = 16,162,475
    file 0xe54 numRepRecords = 3696 firstVLSN = 16,162,476 lastVLSN = 16,166,171
    file 0xe55 numRepRecords = 3624 firstVLSN = 16,166,172 lastVLSN = 16,169,795
    file 0xe56 numRepRecords = 4537 firstVLSN = 16,169,796 lastVLSN = 16,174,332
    file 0xe57 numRepRecords = 7147 firstVLSN = 16,174,333 lastVLSN = 16,181,479
    file 0xe58 numRepRecords = 2186 firstVLSN = 16,181,480 lastVLSN = 16,183,665
    file 0xe59 numRepRecords = 6190 firstVLSN = 16,183,666 lastVLSN = 16,189,855
    file 0xe5a numRepRecords = 3280 firstVLSN = 16,189,856 lastVLSN = 16,193,135
    file 0xe5b numRepRecords = 6070 firstVLSN = 16,193,136 lastVLSN = 16,199,205
    file 0xe5c numRepRecords = 4114 firstVLSN = 16,199,206 lastVLSN = 16,203,319
    file 0xe5d numRepRecords = 1881 firstVLSN = 16,203,320 lastVLSN = 16,205,200
    file 0xe5e numRepRecords = 6265 firstVLSN = 16,205,201 lastVLSN = 16,211,465
    file 0xe5f numRepRecords = 1621 firstVLSN = 16,211,466 lastVLSN = 16,213,086
    file 0xe60 numRepRecords = 5558 firstVLSN = 16,213,087 lastVLSN = 16,218,644
    file 0xe61 numRepRecords = 5816 firstVLSN = 16,218,645 lastVLSN = 16,224,460
    file 0xe62 numRepRecords = 2933 firstVLSN = 16,224,461 lastVLSN = 16,227,393
    file 0xe63 numRepRecords = 3212 firstVLSN = 16,227,394 lastVLSN = 16,230,605
    file 0xe64 numRepRecords = 3416 firstVLSN = 16,230,606 lastVLSN = 16,234,021
    file 0xe65 numRepRecords = 5589 firstVLSN = 16,234,022 lastVLSN = 16,239,610
    file 0xe66 numRepRecords = 4233 firstVLSN = 16,239,611 lastVLSN = 16,243,843
    file 0xe67 numRepRecords = 4209 firstVLSN = 16,243,844 lastVLSN = 16,248,052
    file 0xe68 numRepRecords = 5680 firstVLSN = 16,248,053 lastVLSN = 16,253,732
    file 0xe69 numRepRecords = 2522 firstVLSN = 16,253,733 lastVLSN = 16,256,254
    file 0xe6a numRepRecords = 5901 firstVLSN = 16,256,255 lastVLSN = 16,262,155
    file 0xe6b numRepRecords = 4428 firstVLSN = 16,262,156 lastVLSN = 16,266,583
    file 0xe6c numRepRecords = 4854 firstVLSN = 16,266,584 lastVLSN = 16,271,437
    file 0xe6d numRepRecords = 2903 firstVLSN = 16,271,438 lastVLSN = 16,274,340
    file 0xe6e numRepRecords = 4155 firstVLSN = 16,274,341 lastVLSN = 16,278,495
    file 0xe6f numRepRecords = 5170 firstVLSN = 16,278,496 lastVLSN = 16,283,665
    file 0xe70 numRepRecords = 2330 firstVLSN = 16,283,666 lastVLSN = 16,285,995
    file 0xe71 numRepRecords = 5927 firstVLSN = 16,285,996 lastVLSN = 16,291,922
    file 0xe72 numRepRecords = 4845 firstVLSN = 16,291,923 lastVLSN = 16,296,767
    file 0xe73 numRepRecords = 4208 firstVLSN = 16,296,768 lastVLSN = 16,300,975
    file 0xe74 numRepRecords = 5239 firstVLSN = 16,300,976 lastVLSN = 16,306,214
    file 0xe75 numRepRecords = 1277 firstVLSN = 16,306,215 lastVLSN = 16,307,491
    file 0xe76 numRepRecords = 5528 firstVLSN = 16,307,492 lastVLSN = 16,313,019
    file 0xe77 numRepRecords = 5180 firstVLSN = 16,313,020 lastVLSN = 16,318,199
    file 0xe78 numRepRecords = 2322 firstVLSN = 16,318,200 lastVLSN = 16,320,521
    file 0xe79 numRepRecords = 5540 firstVLSN = 16,320,522 lastVLSN = 16,326,061
    file 0xe7a numRepRecords = 3914 firstVLSN = 16,326,062 lastVLSN = 16,329,975
    ... 0 files at end
    First file: 0xcd6
    Last file: 0xe7a

    If there are big gaps of files that have no VLSNs, there may be something tricky going on with the gating of log cleaning. But this is really more to get a hint of what might be going on -- there are no known "bad" layout patterns that we know of.

    I've asked you to generate a lot of information. If it is too much to post, feel free to maill it to me at linda dot q dot lee at o... com. If you do that, you could skip #2 and #3 and just mail the je.info files, which are generally not that large.

    Linda

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points