Improve DefaultEntryLogger read performance. #4038

horizonzy · 2023-07-26T12:46:42Z

If the BufferChannel is BufferedReadChannel, the size won't change. We can cache the fileSize to avoid time-consuming operation.

Performance tests.

The entry log f file holds 1GB data.

-rw-r--r--@  1 horizon  staff   1.0G  7 26 17:47 f.log

1. Test DefaultEntryLogger.scanEntryLog (10x performance improvement)

    public static void main(String[] args) throws IOException {
        ServerConfiguration serverConfiguration = new ServerConfiguration();
        serverConfiguration.setLedgerDirNames(new String[]{"/Users/horizon/Downloads/bk1/bk-data"});
        DefaultEntryLogger defaultEntryLogger = new DefaultEntryLogger(serverConfiguration);
        long l = System.currentTimeMillis();
        AtomicInteger entryCount = new AtomicInteger();
        defaultEntryLogger.scanEntryLog(15, new EntryLogScanner() {
            @Override
            public boolean accept(long ledgerId) {
                return true;
            }

            @Override
            public void process(long ledgerId, long offset, ByteBuf entry) throws IOException {
                entryCount.incrementAndGet();
            }
        });
        long spend = System.currentTimeMillis() - l;
        System.out.println("Scan entry end, entry count: " + entryCount.get());
        System.out.println("Spend: " + spend);
    }

Before this pr:

Scan entry end, entry count: 17886769
Spend: 37273

After this pr:

Scan entry end, entry count: 17886769
Spend: 3363

2. Test DefaultEntryLogger.readFromLogChannel (30x performance improvement)

    public static void main(String[] args) throws IOException {
        ServerConfiguration serverConfiguration = new ServerConfiguration();
        serverConfiguration.setLedgerDirNames(new String[]{"/Users/horizon/Downloads/bk1/bk-data"});
        DefaultEntryLogger defaultEntryLogger = new DefaultEntryLogger(serverConfiguration);
        long l = System.currentTimeMillis();
        BufferedReadChannel channel = defaultEntryLogger.getChannelForLogId(15);
        int pos = 0;
        //Read total 1gb data from the BufferedReadChannel.
        long gb = 1024 * 1024 * 1024;
        ByteBuf byteBuf = ByteBufAllocator.DEFAULT.heapBuffer(10);
        while (pos < gb) {
            defaultEntryLogger.readFromLogChannel(15, channel, byteBuf, 0);
            pos += byteBuf.readableBytes();
            byteBuf.clear();
        }
        long spend = System.currentTimeMillis() - l;
        System.out.println("Spend: " + spend);
    }

Before this pr:

Spend: 69810

After this pr:

Spend: 2338

dlg99 · 2023-07-26T23:37:15Z

Good idea, great results.

Can you please check that these "Bookie Tests" failures aren't related the change:

Error:  Errors: 
Error:  org.apache.bookkeeper.bookie.DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval
Error:    Run 1: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
Error:    Run 2: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
Error:    Run 3: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
[INFO] 
Error:  org.apache.bookkeeper.bookie.storage.ldb.DbLedgerStorageTest.testEntriesOutOfOrderWithFlush
Error:    Run 1: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
Error:    Run 2: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
Error:    Run 3: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
[INFO] 
Warning:  Flakes: 
Warning:  InterleavedLedgerStorageTest.testConsistencyCheckConcurrentGC
[INFO]   Run 1: PASS
Error:    Run 2: expected:<0> but was:<8354>
Error:    Run 3: expected:<0> but was:<7255>
Error:    Run 4: expected:<0> but was:<7712>

I'll restart the job to see if these are flaps though I don't think these tests flapped before.

horizonzy · 2023-07-27T00:39:04Z

Good idea, great results.

Can you please check that these "Bookie Tests" failures aren't related the change:

Error:  Errors: 
Error:  org.apache.bookkeeper.bookie.DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval
Error:    Run 1: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
Error:    Run 2: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
Error:    Run 3: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
[INFO] 
Error:  org.apache.bookkeeper.bookie.storage.ldb.DbLedgerStorageTest.testEntriesOutOfOrderWithFlush
Error:    Run 1: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
Error:    Run 2: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
Error:    Run 3: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
[INFO] 
Warning:  Flakes: 
Warning:  InterleavedLedgerStorageTest.testConsistencyCheckConcurrentGC
[INFO]   Run 1: PASS
Error:    Run 2: expected:<0> but was:<8354>
Error:    Run 3: expected:<0> but was:<7255>
Error:    Run 4: expected:<0> but was:<7712>

I'll restart the job to see if these are flaps though I don't think these tests flapped before.

I have checked the testAppendLedgersMapOnCacheRemoval and testEntriesOutOfOrderWithFlush. The problem is that the BufferedReadChannel and BufferedLogChannel share the same FileChannel. When the BufferedReadChannel finishes reading the fileSize, the BufferedLogChannel writes new data into the file. I will verify if this situation exists. In theory, the FileChannel read by the BufferedLogChannel should not write any new data.

horizonzy · 2023-07-27T15:49:50Z

Good idea, great results.

Can you please check that these "Bookie Tests" failures aren't related the change:

Error:  Errors: 
Error:  org.apache.bookkeeper.bookie.DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval
Error:    Run 1: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
Error:    Run 2: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
Error:    Run 3: DefaultEntryLogTest.testAppendLedgersMapOnCacheRemoval:1223 » IO Not all ledge...
[INFO] 
Error:  org.apache.bookkeeper.bookie.storage.ldb.DbLedgerStorageTest.testEntriesOutOfOrderWithFlush
Error:    Run 1: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
Error:    Run 2: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
Error:    Run 3: DbLedgerStorageTest.testEntriesOutOfOrderWithFlush:400 » IO Bad entry read fro...
[INFO] 
Warning:  Flakes: 
Warning:  InterleavedLedgerStorageTest.testConsistencyCheckConcurrentGC
[INFO]   Run 1: PASS
Error:    Run 2: expected:<0> but was:<8354>
Error:    Run 3: expected:<0> but was:<7255>
Error:    Run 4: expected:<0> but was:<7712>

I'll restart the job to see if these are flaps though I don't think these tests flapped before.

Fixed.

eolivelli

Overall I support this change.

But I am not sure about the 'name' name.
Can we fins something that explains better the purpose of this property?

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/EntryLogger.java

Reidddddd · 2023-07-31T02:57:40Z

I feel Enrico's purpose is to require some method docs to explain why it needs the method name or type (anyway)

And i skimmed the changes, seems if (xxx instance of DefaultEntryLogger) will resolve it? no need to add this method

horizonzy · 2023-08-01T08:52:44Z

And i skimmed the changes, seems if (xxx instance of DefaultEntryLogger) will resolve it? no need to add this method

Using instanceOf is not a good practice, It violates polymorphism.

Reidddddd · 2023-08-01T09:33:51Z

And i skimmed the changes, seems if (xxx instance of DefaultEntryLogger) will resolve it? no need to add this method

Using instanceOf is not a good practice, It violates polymorphism.

compactingLogWriteDone is only a private method in TransactionalEntryLogCompactor.java, not a common method in AbstractLogCompactor.

What you did, in order to serve a private function in a concrete sub class, you added a function and parameters for other classes which don't need them

When you are talking about polymorphism, polymorphism allows each sub-class has its own behaviour, you are enforcing all the sub-class to satisfy a concrete need not a common need, you are the one who breaks polymorphism...

horizonzy · 2023-08-01T10:02:12Z

And i skimmed the changes, seems if (xxx instance of DefaultEntryLogger) will resolve it? no need to add this method

Using instanceOf is not a good practice, It violates polymorphism.

compactingLogWriteDone is only a private method in TransactionalEntryLogCompactor.java, not a common method in AbstractLogCompactor.

What you did, in order to serve a private function in a concrete sub class, you added a function and parameters for other classes which don't need them

When you are talking about polymorphism, polymorphism allows each sub-class has its own behaviour, you are enforcing all the sub-class to satisfy a concrete need not a common need, you are the one who breaks polymorphism...

Ok, that makes sense. I would like to public an interface to do the work.

horizonzy · 2023-08-01T11:48:54Z

I feel Enrico's purpose is to require some method docs to explain why it needs the method name or type (anyway)

And i skimmed the changes, seems if (xxx instance of DefaultEntryLogger) will resolve it? no need to add this method

Finally, take your suggestion, thanks.

Reidddddd · 2023-08-02T04:33:47Z

+1

horizonzy · 2023-08-03T01:54:12Z

rerun failure checks

hangc0276

Great job! Would you please add a test to protect this change? Especially for the sealed flag

hangc0276 · 2023-08-09T08:46:46Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BufferedReadChannel.java


-    public BufferedReadChannel(FileChannel fileChannel, int readCapacity) {
+    public BufferedReadChannel(FileChannel fileChannel, int readCapacity, boolean sealed) {


Do we need to keep the original constructor method and create a new one with sealed flag? Because the BufferedReadChannel class is public and the constructor is also public, other applications may use this channel to create instances. If we change the constructor directly, it will break the compatibility with the old versions.

Make sense.

zymap · 2023-08-10T02:10:55Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/EntryLoggerAllocator.java

        }
    }

+    void clearCompactingLogId() {
+        writingCompactingLogId = -1;


Do we need to guard this by synchronized (createCompactionLogLock)? It seems not possible to have race conditions, but I see the createNewLogForCompaction(File dirForNextEntryLog) is guarded.

No need this, the createNewLogForCompaction and clearCompactingLogId are serial.

No need this, the createNewLogForCompaction and clearCompactingLogId are serial.

What do you mean?

Just wondering if there's a chance that writingLogId and writingCompactingLogId field changes wouldn't be visible for another thread that reads these fields.

No need this, the createNewLogForCompaction and clearCompactingLogId are serial.

What do you mean?

The method createNewLogForCompaction is synchronized. It creates compact file one by one, so the previous log file id can't override the next log file id.

Just wondering if there's a chance that writingLogId and writingCompactingLogId field changes wouldn't be visible for another thread that reads these fields.

Make sense, make it volatile.

horizonzy · 2023-09-06T07:19:27Z

From the user report, they cherry-pick this commit, and they found that there is a problem about it.

Caused by: org.apache.bookkeeper.bookie.DefaultEntryLogger$EntryLookupException$MissingEntryException: pos 1027337410 (entry 135 for ledgerId 574) past end of entryLog 46

I will try to find the problem with them.

horizonzy · 2023-09-07T16:05:28Z

From the user report, they cherry-pick this commit, and they found that there is a problem about it.
Caused by: org.apache.bookkeeper.bookie.DefaultEntryLogger$EntryLookupException$MissingEntryException: pos 1027337410 (entry 135 for ledgerId 574) past end of entryLog 46
I will try to find the problem with them.

The user config setEntryLogPerLedgerEnabled=true, so the defaultEntryLogger will write multi entry log file at the same time, so the sealed flag is not set correctly.

If the config setEntryLogPerLedgerEnabled=true, the sealed flag always be false.

horizonzy · 2023-09-07T16:05:43Z

Great job! Would you please add a test to protect this change? Especially for the sealed flag

Done.

Reidddddd · 2023-09-18T07:36:31Z

Hope to see this improvement in the next release (thumb up

eolivelli

Lgtm

hangc0276 · 2024-02-05T06:10:54Z

@merlimat @lhotari Please help take a look at this PR, thanks.

lhotari · 2024-02-05T10:54:01Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BufferedReadChannel.java

+    public long size() throws IOException {
+        if (sealed) {
+            if (fileSize == -1) {
+                fileSize = validateAndGetFileChannel().size();
+            }
+            return fileSize;
+        } else {
+            return validateAndGetFileChannel().size();
+        }
+    }


Would there be a benefit to override this logic in BufferedChannel class where the position (and possibly unpersistedBytes) field information would be leveraged? Doesn't position contain the file size when it's writable?

The FileChnanel doesn't have position field and the position() method will trigger the OS system call

@hangc0276 I was referring to

bookkeeper/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BufferedChannel.java

Lines 49 to 52 in 2209734

/**

* The absolute position of the next write operation.

*/

protected volatile long position;

in BufferedChannel class. In the case that the instance is a BufferedChannel class, perhaps it could use that information?

Is the challenge in that case that the same file could have a BufferedReadChannel instance and a BufferedChannel instance at the same time?

I'm not got you fully, the BufferedChannel means the corresponding file is writing, it override the BufferedReadChannel#read method, it know the file end position.

Is the challenge in that case that the same file could have a BufferedReadChannel instance and a BufferedChannel instance at the same time?

#4038 (comment)
The test contains the case.

lhotari · 2024-02-05T11:01:09Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/EntryLoggerAllocator.java

+    public boolean isSealed(long logId) {
+        return logId != writingLogId && logId != writingCompactingLogId;
+    }


Isn't this misleading if it is called "isSealed"?

isSealed means that the entry log file will no longer be written to, we needn't care that the file size change.

merlimat · 2024-02-11T16:12:51Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/BufferedReadChannel.java

+    @Override
+    public long size() throws IOException {
+        if (sealed) {
+            if (fileSize == -1) {


nit: if the file is already "sealed", should we read the size in the constructor? This way we wouldn't have any concurrency issues here if 2 threads call size() at the size time.

The size() would throw IOException, I don't want to make the constructor announce the exception, so make the fileSize double check to avoid concurrency.

* Avoid system call to improve read performance. * Fix ci. * Add comments for getCurrentWritingLogId * Fix ci. * Consider compacting log. * Fix checkstyle. * Address the comment. * Address comment. * Address the comments. * Add tests. * Fix checkstyle. * address the comments. * Fix concurrency problem.

Avoid system call to improve read performance.

c2bd20b

shoothzj approved these changes Jul 27, 2023

View reviewed changes

Fix ci.

071c9fd

horizonzy added 4 commits July 28, 2023 00:07

Add comments for getCurrentWritingLogId

d27256f

Fix ci.

f6f7b36

Consider compacting log.

95d40a9

Fix checkstyle.

9d25baf

eolivelli requested changes Jul 30, 2023

View reviewed changes

bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/storage/EntryLogger.java Outdated Show resolved Hide resolved

Address the comment.

47ed592

Address comment.

114294c

horizonzy closed this Aug 2, 2023

horizonzy reopened this Aug 2, 2023

hangc0276 requested review from merlimat, hangc0276, dlg99, zymap, wenbingshen and StevenLuMT August 9, 2023 08:32

hangc0276 assigned horizonzy Aug 9, 2023

hangc0276 added the area/bookie label Aug 9, 2023

hangc0276 added the type/improvement label Aug 9, 2023

hangc0276 added this to the 4.17.0 milestone Aug 9, 2023

hangc0276 reviewed Aug 9, 2023

View reviewed changes

zymap reviewed Aug 10, 2023

View reviewed changes

Address the comments.

f8a68ef

Add tests.

2b22752

Fix checkstyle.

5ad1133

eolivelli approved these changes Sep 18, 2023

View reviewed changes

lhotari reviewed Feb 5, 2024

View reviewed changes

hangc0276 approved these changes Feb 5, 2024

View reviewed changes

lhotari reviewed Feb 5, 2024

View reviewed changes

address the comments.

f389666

merlimat approved these changes Feb 11, 2024

View reviewed changes

Fix concurrency problem.

1796a4d

merlimat merged commit f5e4a98 into apache:master Feb 12, 2024
20 checks passed

gaozhangmin pushed a commit to gaozhangmin/bookkeeper that referenced this pull request Feb 20, 2024

Improve DefaultEntryLogger read performance. apache#4038

5c785da

gaozhangmin pushed a commit to gaozhangmin/bookkeeper that referenced this pull request Feb 20, 2024

Improve DefaultEntryLogger read performance. apache#4038

b3ea933

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve DefaultEntryLogger read performance. #4038

Improve DefaultEntryLogger read performance. #4038

horizonzy commented Jul 26, 2023 •

edited

Loading

dlg99 commented Jul 26, 2023

horizonzy commented Jul 27, 2023

horizonzy commented Jul 27, 2023

eolivelli left a comment

Reidddddd commented Jul 31, 2023

horizonzy commented Aug 1, 2023

Reidddddd commented Aug 1, 2023

horizonzy commented Aug 1, 2023

horizonzy commented Aug 1, 2023

Reidddddd commented Aug 2, 2023 •

edited

Loading

horizonzy commented Aug 3, 2023

hangc0276 left a comment

hangc0276 Aug 9, 2023

horizonzy Aug 10, 2023

zymap Aug 10, 2023

horizonzy Aug 10, 2023

lhotari Feb 5, 2024

lhotari Feb 5, 2024

horizonzy Feb 10, 2024

horizonzy Feb 10, 2024

horizonzy commented Sep 6, 2023

horizonzy commented Sep 7, 2023

horizonzy commented Sep 7, 2023

Reidddddd commented Sep 18, 2023

eolivelli left a comment

hangc0276 commented Feb 5, 2024

lhotari Feb 5, 2024

hangc0276 Feb 5, 2024

lhotari Feb 5, 2024 •

edited

Loading

horizonzy Feb 10, 2024

lhotari Feb 5, 2024

horizonzy Feb 10, 2024 •

edited

Loading

merlimat Feb 11, 2024

horizonzy Feb 11, 2024


		public BufferedReadChannel(FileChannel fileChannel, int readCapacity) {
		public BufferedReadChannel(FileChannel fileChannel, int readCapacity, boolean sealed) {

	/**
	* The absolute position of the next write operation.
	*/
	protected volatile long position;

Improve DefaultEntryLogger read performance. #4038

Improve DefaultEntryLogger read performance. #4038

Conversation

horizonzy commented Jul 26, 2023 • edited Loading

Performance tests.

1. Test DefaultEntryLogger.scanEntryLog (10x performance improvement)

2. Test DefaultEntryLogger.readFromLogChannel (30x performance improvement)

dlg99 commented Jul 26, 2023

horizonzy commented Jul 27, 2023

horizonzy commented Jul 27, 2023

eolivelli left a comment

Choose a reason for hiding this comment

Reidddddd commented Jul 31, 2023

horizonzy commented Aug 1, 2023

Reidddddd commented Aug 1, 2023

horizonzy commented Aug 1, 2023

horizonzy commented Aug 1, 2023

Reidddddd commented Aug 2, 2023 • edited Loading

horizonzy commented Aug 3, 2023

hangc0276 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

horizonzy commented Sep 6, 2023

horizonzy commented Sep 7, 2023

horizonzy commented Sep 7, 2023

Reidddddd commented Sep 18, 2023

eolivelli left a comment

Choose a reason for hiding this comment

hangc0276 commented Feb 5, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lhotari Feb 5, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

horizonzy Feb 10, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

horizonzy commented Jul 26, 2023 •

edited

Loading

Reidddddd commented Aug 2, 2023 •

edited

Loading

lhotari Feb 5, 2024 •

edited

Loading

horizonzy Feb 10, 2024 •

edited

Loading