Batch deletes trigger multiple observer callbacks instead of one

[alexookah]

[REQUIRED] Step 1: Describe your environment

• Xcode version: 11.5
• Firebase SDK version: 6.8.0
• Firebase Component: Firestore
• Component version: 1.16.0
• Installation method: CocoaPods

[REQUIRED] Step 2: Describe the problem

When observing a whereFilter query, when multiple documents are deleted, the observer callback is called once for every deleted document, instead of being called once with multiple document changes (like additions and modifications do).

The performance of these callbacks is also very poor (OnWatchStreamChange uses 100% cpu).

Observing a whole collection (without a whereFilter) seems to be okay.

Steps to reproduce:

Observe a query that has many documents, then delete multiple documents (using a different device).
The observer callback will be run multiple times, once for each deleted document.

Relevant Code:

db.collection("myCol").whereField("foo", isEqualTo: "bar").addSnapshotListener { querySnapshot, error in 
    print(querySnapshot.documentChanges.count) // this prints "1" multiple times when documents are deleted
}

[thebrianchen]

@alexookah I've tried reproducing your issue in tests by deleting multiple documents using WriteBatch from another instance of Firestore to simulate using a different device (test link), but the snapshot listener consistently receives all the deletes in a single snapshot. Just to confirm, are you using WriteBatch for your batch deletes?

If so, can you provide a repro, or enable verbose logging and share the logs from a local reproduction?

[Stratubas]

@thebrianchen The batched delete is done in a cloud function using something like this:

const batch = db.batch();
for (const id of idsToDelete) {
    batch.delete(db.collection("myCol").doc(id));
}
await batch.commit();

and additions / modifications use similar code (the iOS only reads the data).

[alexookah]

@thebrianchen Using the Simulator the document deletions appear one by one, but using a real device (iPad), they come in small batches (20-50 documents) instead of 500 which is the batch size. For additions and modifications, both the simulator and the real device receive batches of 500 changes.

[thebrianchen]

@alexookah I tried reproducing it locally in a query with many documents and used a batch size of 500 without success. Could you enable verbose logging and share the logs from the batch deletes? Thanks!

[alexookah]

Here are the verbose logs (zip file)

and this is my code:

let now1 = Date()
print("MAAAA before observe", now1)

db.collection("pois").whereField("mapId", isEqualTo: mapId).addSnapshotListener { querySnapshot, error in
    guard let snapshot = querySnapshot else {
        log.error("Error fetching pois/mapid:\(mapId) snapshots: \(error!)")
        return
    }
    
    let now = Date()
    print("MAAAA \(snapshot.documentChanges.count) documentChanges to process ", now)
    
    snapshot.documentChanges.forEach { documentChange in
        let document = documentChange.document
        // plus code that uses the document...
    }
    print("MAAAA finished callback", Date().timeIntervalSince(now))
    print("MAAAA finished drawing", Date().timeIntervalSince(now1))
}

[thebrianchen]

Thanks for taking the time to record and share the logs with us!

From the logs, it appears the multiple snapshots you are receiving are a consequence of the limbo resolution performed by the Firestore client. The 500 documents in the batch you deleted were marked as “removed” rather than “deleted” by the Firestore backend, which prompted the client to mark them as being in limbo. The client resolves the limbo documents by looking them up in batches, to avoid overloading the backend. Firestore raises a snapshot callback each time a batch is complete, which results in the multiple callbacks you are observing.

To tell which snapshot contains the guaranteed up-to-date server snapshot, you can include metadata changes in your snapshot listener and filter out any snapshots that have the isFromCache property set to YES. To process complete snapshots, you’ll have to accumulate the intermediate snapshots and process them all at once.

As for the 100% CPU usage by onWatchStreamChange, we will analyze our usage and logic to see what optimizations we can make.

[morganchen12]

Closing since this is working as intended.