Junegunn Choi created HBASE-30377:
-------------------------------------
Summary: WALInputFormat drops WAL files that span the requested
time range
Key: HBASE-30377
URL: https://issues.apache.org/jira/browse/HBASE-30377
Project: HBase
Issue Type: Bug
Reporter: Junegunn Choi
h2. Problem
When we run {{WALPlayer}}, we can specify a time range via {{wal.start.time}}
and {{wal.end.time}}.
{{WALInputFormat.addFile}} picks a WAL file only when the timestamp in its
filename falls inside the requested range:
{code:java}
if (timestamp <= endTime && timestamp >= startTime) {
{code}
But that timestamp is the WAL file's creation time. A WAL file stays open until
it rolls, so a file created before {{startTime}} can still contain entries
inside the range. The check throws the whole file away.
For example, asking for entries between 100 and 200:
{noformat}
WAL created at t=50, rolled at t=150 -> contains entries 50..150
50 <= 200 ok
50 >= 100 fails -> file skipped
lost: every entry in 100..150
{noformat}
h2. Fix
We should not compare {{wal.start.time}} with the creation time. Instead, we
should compare it with the last modified time, which is not final until the
file is closed.
{code:java}
if (timestamp > endTime) {
skip;
} else if (lfs.getModificationTime() < startTime && isClosed(fs,
lfs.getPath())) {
skip;
} else {
keep;
}
{code}
{{DistributedFileSystem.isFileClosed}} appears to be relatively cheap, measured
at 0.41 ms per call against a local NameNode, and it is short circuited.
{{wal.start.time}} defaults to {{Long.MIN_VALUE}}, so a job that does not ask
for a start time never reaches the call at all, and a job that does pays it
only for the files that the modification time alone would prune.
h2. An existing test asserted the old behavior
{{TestWALRecordReader.testPartialRead}} writes two entries into a WAL, rolls
it, then writes more into the next one. The second entry of the first file is
written at exactly {{ts + 1}}, and the test then queries with
{{wal.start.time}} set to {{ts + 1}}:
{code:java}
jobConf.setLong(WALInputFormat.START_TIME_KEY, ts + 1);
jobConf.setLong(WALInputFormat.END_TIME_KEY, ts1 + 1);
splits = input.getSplits(MapreduceTestingShim.createJobContext(jobConf));
assertEquals(1, splits.size());
// Only the 1st entry from the 2nd file is in-range.
testSplit(splits.get(0), Bytes.toBytes("3"));
{code}
That entry is inside the requested range, but its file was created before
{{startTime}} and is dropped, so the test asserts the loss as if it were
correct. It is corrected here to expect both splits, and the entry that was
being lost is now asserted to come back.
h2. Workaround
On released versions, set {{wal.start.time}} to the point you want minus
{{hbase.regionserver.logroll.period}} (default 3600000 ms). Periodic rolls are
forced, so no WAL stays open longer than that.
This is not free. We replay extra WAL entries.
h2. Behavior
|| WAL || before || after ||
| closed, last written before the window | skipped | skipped |
| closed, spans the start of the window | skipped, entries lost | kept |
| still open, created before the window | skipped, entries lost | kept |
| created inside the window | kept | kept |
| created after the window | skipped | skipped |
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
