Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Large increase in Firestore initialisation time in 8.8.0 #8791

Closed
paulharter opened this issue Oct 12, 2021 · 11 comments · Fixed by #8850
Closed

Large increase in Firestore initialisation time in 8.8.0 #8791

paulharter opened this issue Oct 12, 2021 · 11 comments · Fixed by #8850
Assignees
@schmidt-sebastian
Labels
api: firestore

Comments

@paulharter
Copy link
Contributor

[REQUIRED] Step 1: Describe your environment

  • Xcode version: 13.0
  • Firebase SDK version: 8.8.0
  • Installation method: CocoaPods
  • Firebase Component: Firestore

[REQUIRED] Step 2: Describe the problem

Steps to reproduce:

After updating (unfortunately several things at once) to iOS 14.8, xcode 13 and SDK 8.8.0 (from 7.4.0) I am getting a change in behaviour in startup and initialisation of the SDK.

I am now getting a long pause before the SDK responds to the first request. This request is a simple get on a ref and only checks that the user is authenticated at all, not fetching any other docs in the rules. With 7.4.0 this would complete in roughly 1s, now I am seeing delays of 6s in iPad, 28s on Catalyst. All subsequent gets take 50-80ms.

This makes the app almost unusable.

After deleting app and data the time goes back down to a little over a second in iOS, which implies that size/state of database can cause considerable delay on startup.

Is this something you are aware of?

Is there a new behaviour, maybe more indexing, on startup? If so can I turn it off?

I'm not sure if this is related just to the size of a healthy database or an indication that something is wrong (accumulation of failed writes?)

Is there any way I can debug this? I think there is an envar for verbose Firestore logging but cant remember it.

Thanks
@paulharter
Copy link
Contributor Author

A bit more detail:

It looks like the first thing the SDK does on startup, that takes most of the delay is prepare a large transaction into levelDB (possibly of all the documents?):

2021-10-12 13:09:14.198671+0100 Edit Board[21661:197715] 8.8.0 - [Firebase/Core][I-COR000033] Data Collection flag is not set.
2021-10-12 13:09:14.432372+0100 Edit Board[21661:197024] [UIFocus] Focus system disabled
2021-10-12 13:09:14.438762+0100 Edit Board[21661:197024] [UIFocus] Focus system enabled
2021-10-12 13:09:14.468170+0100 Edit Board[21661:197717] [logging] volume does not support data protection, stripping SQLITE_OPEN_FILEPROTECTION_* flags
2021-10-12 13:09:14.469196+0100 Edit Board[21661:197717] [logging] volume does not support data protection, stripping SQLITE_OPEN_FILEPROTECTION_* flags
2021-10-12 13:09:14.553907+0100 Edit Board[21661:197716] [connection] nw_endpoint_handler_set_adaptive_read_handler [C2.1 142.250.187.234:443 ready socket-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] unregister notification for read_timeout failed
2021-10-12 13:09:14.553952+0100 Edit Board[21661:197716] [connection] nw_endpoint_handler_set_adaptive_write_handler [C2.1 142.250.187.234:443 ready socket-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] unregister notification for write_timeout failed
2021-10-12 13:09:14.590214+0100 Edit Board[21661:197716] [logging] volume does not support data protection, stripping SQLITE_OPEN_FILEPROTECTION_* flags
2021-10-12 13:09:14.590476+0100 Edit Board[21661:197716] [logging] volume does not support data protection, stripping SQLITE_OPEN_FILEPROTECTION_* flags
2021-10-12 13:09:39.911429+0100 Edit Board[21661:197717] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Rewrite Targets Canonical Ids: 171978 changes (0 bytes):
@paulharter
Copy link
Contributor Author

kept everything else the same and reverted to 7.4.0

The first commit to levelDB is always empty and no significant delay:

2021-10-12 16:55:51.732988+0100 Edit Board[40455:323823] 7.4.0 - [Firebase/Core][I-COR000033] Data Collection flag is not set.
2021-10-12 16:55:51.743449+0100 Edit Board[40455:323747] [connection] nw_endpoint_handler_set_adaptive_read_handler [C1.1 34.120.195.249:443 ready socket-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] unregister notification for read_timeout failed
2021-10-12 16:55:51.743501+0100 Edit Board[40455:323747] [connection] nw_endpoint_handler_set_adaptive_write_handler [C1.1 34.120.195.249:443 ready socket-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, dns)] unregister notification for write_timeout failed
2021-10-12 16:55:51.936125+0100 Edit Board[40455:323098] [UIFocus] Focus system disabled
2021-10-12 16:55:51.942477+0100 Edit Board[40455:323098] [UIFocus] Focus system enabled
2021-10-12 16:55:51.991847+0100 Edit Board[40455:323765] [logging] volume does not support data protection, stripping SQLITE_OPEN_FILEPROTECTION_* flags
2021-10-12 16:55:51.992989+0100 Edit Board[40455:323765] [logging] volume does not support data protection, stripping SQLITE_OPEN_FILEPROTECTION_* flags
2021-10-12 16:55:52.032928+0100 Edit Board[40455:323841] 7.4.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start LevelDB: 0 changes (0 bytes):>
@schmidt-sebastian
Copy link
Contributor

@paulharter Thanks for reporting this.

What you are seeing is the result of a schema migration. We sometimes perform these migrations to prepare for new features or to improve the overall usability of the SDK. The migration that runs here "Rewrite Targets Canonical Ids" improves the performance of Query evaluation once completed. These schema upgrades should only run once and once completed, startup should be as fast (if not faster) than before.

Note that based on the number of changes written it appears that you have a lot of Query data in your cache. It might make sense for you to lower the cache size or to clear persisted data entirely before you perform the upgrade.
@paulharter
Copy link
Contributor Author

Hi @schmidt-sebastian

Thank you for explaining but I think the migration mechanism isn't working properly. Rather than just running once it runs every time on startup, growing a little each time. It doesn't realise that it ran the previous time. So the app just get slower and slower on startup.

Also is there a way to know that such a migration is going to happen? Do you document somewhere which versions will perform a migration?
@schmidt-sebastian
Copy link
Contributor

@paulharter Can you tell us whether the migrations ever finish? If you are able to use the SDK (write, read a document) then the migrations should have completed and should not run the next time around. You can also look for the log line "Start LevelDB."
@paulharter
Copy link
Contributor Author

@schmidt-sebastian

It appears to add and lots of changes to levelDB and then perform an empty commit.

The SDK seems to work fine again after this.

2021-10-19 16:26:30.504252+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Core][I-COR000001] Configuring the default app.
...
2021-10-19 16:26:30.693265+0100 Edit Board[628:65274] 8.8.0 - [Firebase/Firestore][I-FST000001] Initializing. Current user: person_5b124a37-aff2-48ec-bb72-184af1434944
2021-10-19 16:26:30.694704+0100 Edit Board[628:65274] 8.8.0 - [Firebase/Firestore][I-FST000001] Using /var/mobile/Containers/Data/Application/FE5B6523-C114-4744-BF96-A6AA944DB6C0/Library/Application Support/firestore/__FIRAPP_DEFAULT/roughcutpro-uk-dev/main for LevelDB storage
...
2021-10-19 16:26:30.713197+0100 Edit Board[628:65274] 8.8.0 - [Firebase/Core][I-COR000033] Data Collection flag is not set.
...
2021-10-19 16:26:31.875447+0100 Edit Board[628:65286] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Rewrite Targets Canonical Ids: 4845 changes (0 bytes):
  - Put [query_target: canonical_id=annotation|f:media_id==video_02813970-2A05-4590-8E7C-D1DC24527047collection_id==collection_34C72948-C724-4F9B-A031-2B51B213EDF7|ob:createddesc__name__desc target_id=292] (0 bytes)
  - Put [query_target: canonical_id=annotation|f:media_id==video_FD27D97C-8F0F-4658-9CCD-426556BD31BEcollection_id==collection_34C72948-C724-4F9B-A031-2B51B213EDF7|ob:createddesc__name__desc target_id=8904] (0 bytes)
  - Put [query_target: canonical_id=clip/clip_1E3953FF-4428-4742-A395-69511E8F7B13|f:|ob:__name__asc target_id=58] (0 bytes)
  - Put [query_target: canonical_id=clip/clip_3C0E28FA-CC57-48FB-8033-6C1B0E0588D3|f:|ob:__name__asc target_id=50] (0 bytes)
  - Put [query_target: canonical_id=clip/clip_74B004C4-6986-4AB9-9EAD-FE9C401BE038|f:|ob:__name__asc target_id=220] (0 bytes)
  - Put [query_target: canonical_id=clip/clip_7D83C245-F552-4FA4-9C4D-70311C7E8D36|f:|ob:__name__asc target_id=54] (0 bytes)

... many more similar

  - Put [query_target: canonical_id=task|f:state==1_activechannel==device_EFD7B0E2-0C67-40FF-88FD-3288A0128704_downloadlease<time(1634053638,981691000)|ob:leaseasc__name__asc|l:1 target_id=524] (0 bytes)
  - Put [query_target: canonical_id=task|f:state==1_activechannel==device_EFD7B0E2-0C67-40FF-88FD-3288A0128704_dow<…>
2021-10-19 16:26:31.888438+0100 Edit Board[628:65286] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start LevelDB: 0 changes (0 bytes):>
2021-10-19 16:26:31.903366+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Start MutationQueue: 0 changes (0 bytes):>
2021-10-19 16:26:31.903514+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction NextMutationBatchAfterBatchID: 0 changes (0 bytes):>
2021-10-19 16:26:31.903760+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Allocate target: 0 changes (0 bytes):>
2021-10-19 16:26:31.904223+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] Using full collection scan to execute query: Query(canonical_id=session/session_3uu0dtz5vcwdo29hv9k532laowk8tg49voe877jlndjn8fxyo9|f:|ob:__name__asc)
2021-10-19 16:26:31.904787+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction ExecuteQuery: 0 changes (0 bytes):>
2021-10-19 16:26:31.905437+0100 Edit Board[628:64993]   local device ID: device_EFD7B0E2-0C67-40FF-88FD-3288A0128704
2021-10-19 16:26:31.905581+0100 Edit Board[628:64993] session device ID: device_EFD7B0E2-0C67-40FF-88FD-3288A0128704
2021-10-19 16:26:31.905806+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] WatchStream (2839d0918) start
2021-10-19 16:26:31.906151+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Auth][I-AUT000002] Token auto-refresh enabled.
2021-10-19 16:26:31.906227+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Auth][I-AUT000004] Token auto-refresh scheduled in 00:00 for the new token.
2021-10-19 16:26:31.906290+0100 Edit Board[628:65276] 8.8.0 - [Firebase/Firestore][I-FST000001] Committing transaction: <LevelDbTransaction Allocate target: 0 changes (0 bytes):>
@schmidt-sebastian
Copy link
Contributor

This is really strange. I don't see how the SDK would function if it did not commit the schema changes beforehand. Is this issue isolated to a specific device? If so, have you tried to clear persistence to see if this is reproducible?

We have been using the same schema upgrade logic since we launched the client initially. This does not mean that it is not broken, it just means that I am a bit perplexed.
@paulharter
Copy link
Contributor Author

Very odd. The same thing happens on iPhone, iPad and catalyst. It happens after deleting and reinstalling app.

Maybe I am doing something non-standard in how I'm setting up the app? I will have a look at this.

Maybe there is something about my data that is causing the issue? I have a key "_id" (inherited from couchDB behaviour and helps pagination indexing) in every document that holds its id, might this clash with something?

How does it know it should upgrade schema? Something persisted on device file system? Something missing from device file system? (maybe I'm deleting it accidentally?)
@paulharter
Copy link
Contributor Author

@schmidt-sebastian

I've just had a look at the migration code for levelDB - it looks like migration 7 is missing the call to SaveVersion that all the other migrations have at the end.
@schmidt-sebastian
Copy link
Contributor

@paulharter Oh no. Thanks for digging this up.
@schmidt-sebastian schmidt-sebastian mentioned this issue Oct 21, 2021
Merged
@paulharter
Copy link
Contributor Author

no problem - thanks for getting fix into next build so quickly
@efstathiosntonas efstathiosntonas mentioned this issue Oct 27, 2021
Closed
10 tasks
@firebase firebase locked and limited conversation to collaborators Nov 22, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
api: firestore
4 participants
@paulharter @morganchen12 @schmidt-sebastian @google-oss-bot