Hi team I m trying to use deep store with split commits serv Apache Pinot #troubleshooting

Hi team, I’m trying to use deep store with split c...

Gerrit van Doorn

07/29/2022, 7:03 PM

Hi team, I’m trying to use deep store with split commits (server uploads). Currently they are failing due to timeout errors (still need to investigate this on our end) but I’m seeing the following log messages in the controller log:

Copy code

2022/07/29 17:37:10.353 INFO [LLCSegmentCompletionHandlers] [grizzly-http-server-38] Response to segmentCommitEndWithMetadata for segment:events__2__0__20220729T1717Z is:{"offset":-1,"status":"COMMIT_SUCCESS","isSplitCommitType":false,"streamPartitionMsgOffset":null,"buildTimeSec":-1}

I’m just wondering why it says

isSplitCommitType":false

when both controller and server configs specify

pinot.server.instance.enable.split.commit=true

and

controller.enable.split.commit=true

Jackie

07/29/2022, 10:23 PM

Can you please check if you have duplicate config? E.g. having

controller.enable.split.commit

configured twice

Gerrit van Doorn

07/30/2022, 2:30 AM

My config does not have that twice

Jackie

07/30/2022, 6:00 PM

You may refer to this doc for the required settings (which you might already do): https://docs.pinot.apache.org/operators/operating-pinot/decoupling-controller-from-the-data-path

Jackie

07/30/2022, 6:01 PM

Do check if the config has duplicate key. It might give unexpected behavior when there are duplicate keys

Gerrit van Doorn

07/30/2022, 6:05 PM

I also just noticed (finally got it working to have the servers copy data to deep store) that the controller does a copyDir once a server has uploaded the data. Doesn’t this mean that with systems like S3 copy the data locally and re-upload it, making the controller still a bottleneck?

Jackie

07/30/2022, 6:07 PM

That should no be the case. Server should upload the data, and controller only needs to process the metadata

Gerrit van Doorn

07/31/2022, 6:50 PM

Hmm strange. I’ve added log statements for each of the PinotFS methods and I see a clear DO_MOVE being logged together with COPY_TO_LOCAL_FILE + COPY_FROM_LOCAL_FILE. Let me add the logs related to 1 segment in the controller log.

Gerrit van Doorn

07/31/2022, 6:51 PM

controller log statements regarding events__1__8__20220731T1621Z.txt

Gerrit van Doorn

07/31/2022, 6:54 PM

doMove uses copyDir because the backend does not support atomic moves. Even if it did, it would be doing more than updating metadata.

Gerrit van Doorn

07/31/2022, 10:40 PM

Which I’m assuming is coming from https://github.com/apache/pinot/blob/release-0.10.0/pinot-controller/src/main/java[…]troller/helix/core/realtime/PinotLLCRealtimeSegmentManager.java

Gerrit van Doorn

07/31/2022, 10:42 PM

Note that I’m currently using 0.10.0, maybe things have changed ?

Jackie

07/31/2022, 11:52 PM

Based on the log I don't think split commit is enabled, and that is why I was asking about the instance config

Jackie

07/31/2022, 11:52 PM

Can you paste the controller config you are using?

Gerrit van Doorn

07/31/2022, 11:56 PM

The exact config is:

Copy code

controller.data.dir=<os://FOO-PINOT-DEEP-STORE/segments>
controller.local.temp.dir=/tmp/pinot/controller/temp
controller.helix.cluster.name=PinotCluster
controller.port=9000
pinot.set.instance.id.to.hostname=true
controller.zk.str=localhost:2185

pinot.controller.storage.factory.class.os=com.company.ObjectStorePinotFS
pinot.controller.storage.factory.os.some_config_param = foo
pinot.controller.segment.fetcher.protocols=file,http,os
controller.allow.hlc.tables=false
controller.enable.split.commit=true
controller.realtime.segment.deepStoreUploadRetryEnabled=true

Gerrit van Doorn

07/31/2022, 11:57 PM

In the log we see it being set to true here:

Copy code

2022/07/31 17:21:59.850 INFO [LLCSegmentCompletionHandlers] [grizzly-http-server-25] Response to segmentConsumed for segment:events__1__8__20220731T1621Z is :{"offset":618548030,"status":"COMMIT","isSplitCommitType":true,"controllerVipUrl":"<http://foo4g-rf3-28a.sjc.company.com:9000>","buildTimeSec":126,"streamPartitionMsgOffset":"618548030"}

but in a later request:

Copy code

2022/07/31 17:22:07.371 INFO [LLCSegmentCompletionHandlers] [grizzly-http-server-26] Response to segmentCommitStart for segment:events__1__8__20220731T1621Z is:{"offset":-1,"status":"COMMIT_CONTINUE","isSplitCommitType":false,"buildTimeSec":-1,"streamPartitionMsgOffset":null}

and finally:

Copy code

2022/07/31 17:22:16.981 INFO [LLCSegmentCompletionHandlers] [grizzly-http-server-27] Response to segmentCommitEndWithMetadata for segment:events__1__8__20220731T1621Z is:{"offset":-1,"status":"COMMIT_SUCCESS","isSplitCommitType":false,"buildTimeSec":-1,"streamPartitionMsgOffset":null}

Jackie

07/31/2022, 11:59 PM

Interesting. How about the server config and log?

Gerrit van Doorn

08/01/2022, 12:07 AM

server conf

Copy code

pinot.cluster.name=PinotCluster
pinot.server.instance.realtime.alloc.offheap=true
pinot.set.instance.id.to.hostname=true
pinot.zk.server=localhost:2185
pinot.server.netty.port=7000
pinot.server.adminapi.port=7500
pinot.server.instance.dataDir=/tmp/pinot/server/data
pinot.server.instance.segmentTarDir=/tmp/pinot/server/segments

pinot.server.instance.segment.store.uri=<os://FOO-PINOT-DEEP-STORE/segments>
pinot.server.instance.enable.split.commit=true
pinot.server.storage.factory.class.os=com.company.ObjectStorePinotFS
pinot.server.segment.fetcher.protocols=file,http,os
pinot.server.segment.fetcher.os.class=org.apache.pinot.common.utils.fetcher.PinotFSSegmentFetcher

Gerrit van Doorn

08/01/2022, 12:16 AM

server log for the same segment:

Copy code

2022/07/31 17:22:00.560 INFO [SegmentIndexCreationDriverImpl] [events__1__8__20220731T1621Z] Start building IndexCreator!
2022/07/31 17:22:05.503 INFO [SegmentIndexCreationDriverImpl] [events__1__8__20220731T1621Z] Finished records indexing in IndexCreator!
2022/07/31 17:22:05.983 INFO [SegmentIndexCreationDriverImpl] [events__1__8__20220731T1621Z] Finished segment seal!
2022/07/31 17:22:05.983 INFO [SegmentV1V2ToV3FormatConverter] [events__1__8__20220731T1621Z] Converting segment: /tmp/pinot/server/data/events_REALTIME/_tmp/tmp-events__1__8__20220731T1621Z-1659288119861/events__1__8__20220731T1621Z to v3 format
2022/07/31 17:22:06.247 INFO [SegmentV1V2ToV3FormatConverter] [events__1__8__20220731T1621Z] v3 segment location for segment: events__1__8__20220731T1621Z is /tmp/pinot/server/data/events_REALTIME/_tmp/tmp-events__1__8__20220731T1621Z-1659288119861/events__1__8__20220731T1621Z/v3
2022/07/31 17:22:06.247 INFO [SegmentV1V2ToV3FormatConverter] [events__1__8__20220731T1621Z] Deleting files in v1 segment directory: /tmp/pinot/server/data/events_REALTIME/_tmp/tmp-events__1__8__20220731T1621Z-1659288119861/events__1__8__20220731T1621Z
2022/07/31 17:22:06.292 INFO [CrcUtils] [events__1__8__20220731T1621Z] Computed crc = 2416143356, based on files [/tmp/pinot/server/data/events_REALTIME/_tmp/tmp-events__1__8__20220731T1621Z-1659288119861/events__1__8__20220731T1621Z/v3/columns.psf, /tmp/pinot/server/data/events_REALTIME/_tmp/tmp-events__1__8__20220731T1621Z-1659288119861/events__1__8__20220731T1621Z/v3/index_map, /tmp/pinot/server/data/events_REALTIME/_tmp/tmp-events__1__8__20220731T1621Z-1659288119861/events__1__8__20220731T1621Z/v3/metadata.properties]
2022/07/31 17:22:06.292 INFO [SegmentIndexCreationDriverImpl] [events__1__8__20220731T1621Z] Driver, record read time : 2932
2022/07/31 17:22:06.292 INFO [SegmentIndexCreationDriverImpl] [events__1__8__20220731T1621Z] Driver, stats collector time : 0
2022/07/31 17:22:06.292 INFO [SegmentIndexCreationDriverImpl] [events__1__8__20220731T1621Z] Driver, indexing time : 2009
2022/07/31 17:22:06.292 INFO [LLRealtimeSegmentDataManager_events__1__8__20220731T1621Z] [events__1__8__20220731T1621Z] Successfully built segment in 6431 ms, after lockWaitTime 0 ms
2022/07/31 17:22:07.373 INFO [FileUploadDownloadClient] [events__1__8__20220731T1621Z] Sending request: <http://foo4g-rf3-28a.sjc.company.com:9000/segmentCommitStart?segmentSizeBytes=43878029&buildTimeMillis=6431&streamPartitionMsgOffset=618548030&instance=Server_foo4g-rf3-28a.sjc.company.com_7000&offset=-1&name=events__1__8__20220731T1621Z&rowCount=96739&memoryUsedBytes=91053992> to controller: <http://foo4g-rf3-28a.sjc.company.com|foo4g-rf3-28a.sjc.company.com>, version: Unknown
2022/07/31 17:22:07.373 INFO [ServerSegmentCompletionProtocolHandler] [events__1__8__20220731T1621Z] Controller response {"offset":-1,"streamPartitionMsgOffset":null,"buildTimeSec":-1,"isSplitCommitType":false,"status":"COMMIT_CONTINUE"} for <http://foo4g-rf3-28a.sjc.company.com:9000/segmentCommitStart?segmentSizeBytes=43878029&buildTimeMillis=6431&streamPartitionMsgOffset=618548030&instance=Server_foo4g-rf3-28a.sjc.company.com_7000&offset=-1&name=events__1__8__20220731T1621Z&rowCount=96739&memoryUsedBytes=91053992>
2022/07/31 17:22:07.374 INFO [ObjectStorePinotFS] [pool-22-thread-1] EXISTS: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>
2022/07/31 17:22:07.375 INFO [ObjectStorePinotFS] [pool-22-thread-1] IS_DIRECTORY: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>
2022/07/31 17:22:07.375 INFO [ObjectStorePinotFS] [pool-22-thread-1] Returning pail client for uri: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>
2022/07/31 17:22:07.375 INFO [ObjectStorePinotFS] [pool-22-thread-1] IS_DIRECTORY Listing prefix: segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907/
2022/07/31 17:22:07.954 INFO [ObjectStorePinotFS] [pool-22-thread-1] IS_DIRECTORY Found 0 results for prefix segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907/
2022/07/31 17:22:07.954 INFO [ObjectStorePinotFS] [pool-22-thread-1] EXISTS: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907> is is a file?
2022/07/31 17:22:07.954 INFO [ObjectStorePinotFS] [pool-22-thread-1] Returning pail client for uri: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>
2022/07/31 17:22:07.960 INFO [ObjectStorePinotFS] [pool-22-thread-1] EXISTS_FILE: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907> does not exist
2022/07/31 17:22:07.960 INFO [ObjectStorePinotFS] [pool-22-thread-1] COPY_FROM_LOCAL_FILE: /tmp/pinot/server/data/events_REALTIME/events__1__8__20220731T1621Z.tar.gz of 7401128 bytes => <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>
2022/07/31 17:22:07.960 INFO [ObjectStorePinotFS] [pool-22-thread-1] Returning pail client for uri: <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>
2022/07/31 17:22:08.392 INFO [ObjectStorePinotFS] [pool-22-thread-1] COPY_FROM_LOCAL_FILE Copied /tmp/pinot/server/data/events_REALTIME/events__1__8__20220731T1621Z.tar.gz with size 7401128 to prefix segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907
2022/07/31 17:22:08.392 INFO [PinotFSSegmentUploader] [events__1__8__20220731T1621Z] Successfully upload segment events__1__8__20220731T1621Z to <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907>.
2022/07/31 17:22:16.984 INFO [FileUploadDownloadClient] [events__1__8__20220731T1621Z] Sending request: <http://foo4g-rf3-28a.sjc.company.com:9000/segmentCommitEndWithMetadata?segmentSizeBytes=43878029&buildTimeMillis=6431&streamPartitionMsgOffset=618548030&instance=Server_foo4g-rf3-28a.sjc.company.com_7000&offset=-1&name=events__1__8__20220731T1621Z&location=os%3A%2F%2FFOO-PINOT-DEEP-STORE%2Fsegments%2Fevents%2Fevents__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907&rowCount=96739&memoryUsedBytes=91053992> to controller: <http://foo4g-rf3-28a.sjc.company.com|foo4g-rf3-28a.sjc.company.com>, version: Unknown
2022/07/31 17:22:16.984 INFO [ServerSegmentCompletionProtocolHandler] [events__1__8__20220731T1621Z] Controller response {"offset":-1,"streamPartitionMsgOffset":null,"buildTimeSec":-1,"isSplitCommitType":false,"status":"COMMIT_SUCCESS"} for <http://foo4g-rf3-28a.sjc.company.com:9000/segmentCommitEndWithMetadata?segmentSizeBytes=43878029&buildTimeMillis=6431&streamPartitionMsgOffset=618548030&instance=Server_foo4g-rf3-28a.sjc.company.com_7000&offset=-1&name=events__1__8__20220731T1621Z&location=os%3A%2F%2FFOO-PINOT-DEEP-STORE%2Fsegments%2Fevents%2Fevents__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907&rowCount=96739&memoryUsedBytes=91053992>
2022/07/31 17:22:17.383 INFO [ImmutableSegmentLoader] [events__1__8__20220731T1621Z] Successfully loaded segment: events__1__8__20220731T1621Z with SegmentDirectory
2022/07/31 17:22:17.383 INFO [events_REALTIME-RealtimeTableDataManager] [events__1__8__20220731T1621Z] Adding immutable segment: events__1__8__20220731T1621Z to table: events_REALTIME
2022/07/31 17:22:17.383 INFO [events_REALTIME-RealtimeTableDataManager] [events__1__8__20220731T1621Z] Replaced immutable segment: events__1__8__20220731T1621Z of table: events_REALTIME
2022/07/31 17:22:17.383 INFO [events_REALTIME-RealtimeTableDataManager] [events__1__8__20220731T1621Z] Closing segment: events__1__8__20220731T1621Z of table: events_REALTIME
2022/07/31 17:22:17.383 INFO [feed-events-1] [events__1__8__20220731T1621Z] Trying to close RealtimeSegmentImpl : events__1__8__20220731T1621Z
2022/07/31 17:22:17.383 INFO [feed-events-1] [events__1__8__20220731T1621Z] Segment used 91053992 bytes of memory for 96739 rows consumed in 3600 seconds
2022/07/31 17:22:17.391 INFO [MmapMemoryManager] [events__1__8__20220731T1621Z] Closing buffer org.apache.pinot.segment.spi.memory.PinotByteBuffer@531bab5
2022/07/31 17:22:17.495 INFO [MmapMemoryManager] [events__1__8__20220731T1621Z] Deleted file /tmp/pinot/server/data/events_REALTIME/consumers/events__1__8__20220731T1621Z.0
2022/07/31 17:22:17.496 INFO [events_REALTIME-RealtimeTableDataManager] [events__1__8__20220731T1621Z] Closed segment: events__1__8__20220731T1621Z of table: events_REALTIME
2022/07/31 17:22:30.627 INFO [HelixTaskExecutor] [ZkClient-EventThread-69-localhost:2185] Scheduling message d5c253d4-efbe-4e14-af4f-e572fdcb2a5d: events_REALTIME:events__1__8__20220731T1621Z, CONSUMING->ONLINE
2022/07/31 17:22:30.630 INFO [HelixStateTransitionHandler] [HelixTaskExecutor-message_handle_thread] handling message: d5c253d4-efbe-4e14-af4f-e572fdcb2a5d transit events_REALTIME.events__1__8__20220731T1621Z|[] from:CONSUMING to:ONLINE, relayedFrom: null
2022/07/31 17:22:31.297 INFO [HelixStateTransitionHandler] [HelixTaskExecutor-message_handle_thread] Instance Server_foo4g-rf3-28a.sjc.company.com_7000, partition events__1__8__20220731T1621Z received state transition from CONSUMING to ONLINE on session 1a46823bfca14510, message id: d5c253d4-efbe-4e14-af4f-e572fdcb2a5d
2022/07/31 17:22:31.298 INFO [SegmentOnlineOfflineStateModelFactory$SegmentOnlineOfflineStateModel] [HelixTaskExecutor-message_handle_thread] Segment events__1__8__20220731T1621Z not an instance of LLRealtimeSegmentDataManager. Reporting success for the transition
2022/07/31 17:22:32.550 INFO [HelixTask] [HelixTaskExecutor-message_handle_thread] Message: d5c253d4-efbe-4e14-af4f-e572fdcb2a5d (parent: null) handling task for events_REALTIME:events__1__8__20220731T1621Z completed at: 1659288152550, results: true. FrameworkTime: 586 ms; HandlerTime: 1336 ms.

Jackie

08/01/2022, 12:25 AM

I do see server uploaded the segment to the deep store, not sure why controller still downloaded the segment. I don't have access to the code now. Will get back to you tomorrow

Gerrit van Doorn

08/01/2022, 12:57 AM

The controller tries to rename the segment

Copy code

<os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907> => <os://FOO-PINOT-DEEP-STORE/segments/events/events__1__8__20220731T1621Z>

which might be what is intended. It’s just that this is not atomic on our backend, so it requires a download + upload

Gerrit van Doorn

08/01/2022, 2:11 AM

From what I can see, S3 also has the same strategy:

Copy code

@Override
  public boolean doMove(URI srcUri, URI dstUri)
      throws IOException {
    if (copyDir(srcUri, dstUri)) {
      return delete(srcUri, true);
    }
    return false;
  }

Where hadoop has

rename

Jackie

08/02/2022, 12:15 AM

Verified that server is using split commit properly, and uploaded the segment file to the deep store. The operations on controller is from

pinotFS.move()

which moves the segment file from a temporary location to the final location. One thing I'm not sure is why do we need to first upload the segment to a temporary location, then move to the final location. cc @Neha Pawar @Subbu Subramaniam who have more context on this behavior

Gerrit van Doorn

08/02/2022, 12:16 AM

That is exactly my question. Possibly to prevent a race condition? Either way, the original name could be in the metadata

Subbu Subramaniam

08/02/2022, 12:27 AM

I don't recollect the exact scenario where we needed temporary location initially but I think it was to handle corner cases. Say, a server has very slow network and starts the transfer to deep store. meanwhile, the controller gets impatient and assigns a different server to upload the segment. We don't want these to collide. I have not read the whole thread as yet, but is the temp location causing an issue?

Gerrit van Doorn

08/02/2022, 12:28 AM

It assumes that the backing store for the deep store has an atomic move or remote copy

Subbu Subramaniam

08/02/2022, 12:30 AM

The assumption is the

PinotFS

is implemented. So, the move method is assumed to be there.

Gerrit van Doorn

08/02/2022, 12:33 AM

Yes it is implemented. However, a backing store might not have a move/rename operation, meaning move will have to copyToLocal and copyFromLocal. At that point the controller becomes the bottleneck again. Couldn’t the “temp” filename just be part of the metadata?

Subbu Subramaniam

08/02/2022, 12:34 AM

Not sure what you mean by temp file being part of metadata. temp file location is a part of the

commitEnd

req sent to the controller

Subbu Subramaniam

08/02/2022, 12:35 AM

Does the file system implement

copy

? If so, then the

move

method for that FS (you are using S3, right?) should just call

copy

Jackie

08/02/2022, 12:35 AM

I do see 2

PinotFS

impl S3 and GCS doesn't have

rename

supported, so we do

copy

then

delete

instead

Subbu Subramaniam

08/02/2022, 12:36 AM

So, even

copy

involves the controller?

Gerrit van Doorn

08/02/2022, 12:36 AM

No not using S3. For some reason the eventual filename wants to look like

Copy code

foo__1__8__20220731T1621Z

instead of:

Copy code

foo__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907

The controller could also have said “Hey foo__1__8__20220731T1621Zc406d289-0827-4bf2-a1ba-d699df0b5907 is done, I’m going to use that filename”

Jackie

08/02/2022, 12:41 AM

@Gerrit van Doorn Yeah, this is a good idea. We need to check if we rely on auto-creating the segment path using the data dir and segment name though

Jackie

08/02/2022, 12:41 AM

In your custom PinotFS, can you optimize

move

to by-pass controller?

Gerrit van Doorn

08/02/2022, 12:45 AM

There are plans for this but not in the short term. If Pinot could work around the controller having to depend on renaming it would open up the options for external stores significantly. The controller ideally should only handle the metadata

Jackie

08/02/2022, 12:48 AM

Yes, I agree. There are 2 options: 1. Make server to directly upload the segment to the final location; 2. Make controller use the non-standard segment path as the download url. IMO option 1 is cleaner, but might have race condition.

Jackie

08/02/2022, 12:48 AM

Can you help create a github issue to track this feature request?

Subbu Subramaniam

08/02/2022, 12:57 AM

I am not sure if changing the file name of a segment to be something different than segment name will have other implications (like retention manager, etc.) Otherwise, we could use the temp location provided as the permanent location for the segment. In any case, these kind of changes need to undergo a lot of testing, and may break production use cases for people. I think it is safest if

move

can be optimized to remove the controller from the equation.

Sajjad Moradi

08/02/2022, 5:06 PM

Maybe we can add a isMoveSupported() method to PinotFS interface. Then in commitEnd, where the file is going to be moved from temporary location to the final location, if isMoveSupported evaluates to false, then we just use the temporary location as the final location. This way there's no need to move for FS's that don't support move and also we don't get into the race condition that Subbu mentioned for the FS's that support move.

Subbu Subramaniam

08/02/2022, 5:08 PM

And of course, we need to check other callers of

PinotFS.move()

as well.

➕ 1

2 Views

Open in Slack

Previous Next