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.

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

Firestore emulator crash on export with ~0.5 GB of data #4336

Closed
samborambo305 opened this issue Mar 18, 2022 · 14 comments · Fixed by #4457
Closed

Firestore emulator crash on export with ~0.5 GB of data #4336

samborambo305 opened this issue Mar 18, 2022 · 14 comments · Fixed by #4457

Comments

@samborambo305
Copy link

[REQUIRED] Environment info

firebase-tools: 10.2.2

Platform: macOS

[REQUIRED] Test case

See below

[REQUIRED] Steps to reproduce

Export ~0.56GB of data for the firebase emulator. The emulator crashes and fails to export due to running out of buffer memory. My machine has 64GB ram so this should not be an issue

[REQUIRED] Expected behavior

Export completes successfully

[REQUIRED] Actual behavior

Export crashes with following error:

WARNING: Server fails to send the message, abort the channel!
Mar 18, 2022 12:55:25 PM com.google.cloud.datastore.emulator.firestore.webchannel.FirestoreV1WebChannelAdapter$FirestoreListenHandler onError
WARNING: [ERROR] NETWORK_ERROR ()
Mar 18, 2022 12:55:25 PM com.google.net.webchannel.server.v8.BackChannel add
WARNING: Failed to send a new message due to too many pending messagings in the back channel (10001). May need enable flow control.
Mar 18, 2022 12:55:25 PM com.google.net.webchannel.server.v8.ChannelInternalImpl handle
WARNING: Server fails to send the message, abort the channel!
Mar 18, 2022 12:55:25 PM com.google.cloud.datastore.emulator.firestore.webchannel.FirestoreV1WebChannelAdapter$FirestoreListenHandler onError

<this is repeated for 1.762 million lines>


Mar 18, 2022 1:08:36 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: null
java.nio.BufferOverflowException
    at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:211)
    at com.google.cloud.datastore.emulator.impl.LevelDBLogWriterChannel.writePhysicalRecord(LevelDBLogWriterChannel.java:154)
    at com.google.cloud.datastore.emulator.impl.LevelDBLogWriterChannel.write(LevelDBLogWriterChannel.java:77)
    at com.google.cloud.datastore.emulator.impl.LevelDBLogWriterChannel.write(LevelDBLogWriterChannel.java:56)
    at com.google.cloud.datastore.emulator.impl.ExportImportUtil.writeEntitiesToFile(ExportImportUtil.java:182)
    at com.google.cloud.datastore.emulator.impl.ExportImportUtil.exportEntitiesForSpec(ExportImportUtil.java:157)
    at com.google.cloud.datastore.emulator.impl.ExportImportUtil.exportEntities(ExportImportUtil.java:89)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.exportData(CloudFirestoreV1.java:688)
    at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.exportData(CloudFirestoreV1Router.java:206)
    at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1.lambda$exportData$3(EmulatorAuxiliaryGrpcAdapter.java:98)
    at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter.unary(EmulatorAuxiliaryGrpcAdapter.java:49)
    at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter.access$000(EmulatorAuxiliaryGrpcAdapter.java:28)
    at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1.exportData(EmulatorAuxiliaryGrpcAdapter.java:95)
    at com.google.firestore.emulator.v1.FirestoreEmulatorGrpc$MethodHandlers.invoke(FirestoreEmulatorGrpc.java:631)
    at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:331)
    at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:750)

Mar 18, 2022 1:08:36 PM io.gapi.emulators.netty.HttpHandler$1 onError
INFO: Exception when handling request: UNKNOWN
*** shutting down gRPC server since JVM is shutting down
*** server shut down
@evelant
Copy link

evelant commented Mar 21, 2022

I've found a similar thing with trying to import a 1.5gb production database for local debugging. The emulators just choke even though my machine has 64gb of ram. I opened an issue about it but unfortunately the resolution was "the emulators can't do that". #3929

@jakeleventhal
Copy link

i have 64gb of ram and have the same issue. the emulator ought to support this or at least support a flag to give users the option to specify the size of the process to override the defaults

@evelant
Copy link

evelant commented Mar 22, 2022

IIRC I tried changing java options to give the process much more ram but larger data sets seem to trigger a bug where it just eats up all available memory then crashes or hangs. I gave it something like 32gb for a 1.5gb data set and it still hung the same way as the default memory limit. For some reason the emulator is incapable of loading a larger data set no matter how many resources it is given.

@yuchenshi
Copy link
Member

FYI the JVM behavior for Firestore Emulator can be tweaked using an environment variable, such as export JAVA_TOOL_OPTIONS="-Xmx4g" before starting the emulators. Please try with larger heap sizes and all that -- and let us know if it still fails with more RAM. (We're still working to document this env var. See #2521 for previous discussion)

@yuchenshi yuchenshi changed the title Firebase crash on export with ~0.5 GB of data Firestore emulator crash on export with ~0.5 GB of data Mar 22, 2022
@evelant
Copy link

evelant commented Mar 22, 2022

@yuchenshi in #3929 I tried it with -Xmx48g on my machine with 64gb of ram on a 1.5gb data set... It filled 48gb of ram then failed. There's seemingly a bug that once an import reaches a certain size the emulator gets "stuck" and just continues allocating memory until it runs out and crashes no matter how much you give it.

@yuchenshi
Copy link
Member

@evelant Thanks for the reply. In order to pinpoint the issue, it'd be great if we can look into the particular dump you're trying to import. Would you mind contacting Firebase Support where you can privately share your exports file for reproducing the bug?

@jakeleventhal
Copy link

@evelant @yuchenshi let me know the result of this. I can't send over my data because it contains sensitive information

@jakeleventhal
Copy link

I was able to recreate the issue with the following snippet in Node:

const createDay = (
  id,
  marketplace,
  cogs,
  estimatedFees,
  sales,
  cancels,
  orders,
  units,
  storageFees,
  date,
  productId
) => {
  const dayObject = {
    AtoZClaims: {
      AmazonFees: {},
      Other: {},
      ProductCharges: 0
    },
    Orders: {
      AmazonFees: {
        Commission: 0,
        EstimatedFees: 0,
        FBAPerOrderFulfillmentFee: 0,
        FBAPerUnitFulfillmentFee: 0,
        FBAWeightBasedFee: 0,
        NonAmazonFBAPerUnitFulfillmentFee: 0,
        Other: {}
      },
      Other: {},
      ProductCharges: 0,
      PromoRebates: {
        Orders: 0,
        Shipping: 0
      }
    },
    OtherTransactions: {},
    PaidToAmazon: {},
    PostedOrders: {
      AmazonFees: {
        Commission: 0,
        EstimatedFees: 0,
        FBAPerOrderFulfillmentFee: 0,
        FBAPerUnitFulfillmentFee: 0,
        FBAWeightBasedFee: 0,
        NonAmazonFBAPerUnitFulfillmentFee: 0,
        Other: {}
      },
      Other: {},
      ProductCharges: 0,
      PromoRebates: {
        Orders: 0,
        Shipping: 0
      }
    },
    Refunds: {
      AmazonFees: {},
      Other: {},
      ProductCharges: 0,
      PromoRebates: {
        Orders: 0,
        Shipping: 0
      }
    },
    SellingFees: {
      CostOfAdvertising: 0,
      FBAFees: {},
      Other: {
        Coupons: 0
      }
    },
    ShippingServices: {},
    Ads: {
      Clicks: 0,
      Conversions: 0,
      Cost: 0,
      Impressions: 0,
      Sales: 0,
      Units: 0
    },
    COGS: cogs,
    Counts: {
      CanceledOrders: cancels,
      Orders: orders,
      RefundedUnits: 0,
      ShippedOrders: 0,
      ShippedUnits: 0,
      Units: units
    },
    Date: date,
    FIFOCOGS: 0,
    Marketplace: marketplace,
    ProductData: productId
      ? {
        HasProduct: true,
        ProductId: productId
      }
      : null,
    ShippedCOGS: 0,
    StorageFees: storageFees,
    UserId: id
  };
  dayObject.Orders.AmazonFees.EstimatedFees = Number(estimatedFees);
  dayObject.Orders.ProductCharges += sales;

  return dayObject;
};

const { v4: uuid } = require('uuid');

for (let i = 0; i < 7500; i++) {
  console.log(i);
  await Promise.all([...Array(100)].map(async (value, j) => {
    const collection = `TestCollection${j % 15}`;
    await firestore.collection(collection).doc(uuid()).set(createDay(
      'testid',
      'asdf',
      0,
      0,
      0,
      0,
      0,
      0,
      0,
      '2020-02-02',
      'testid'
    ));
  }));
}

After all 7500 loop iterations complete I get the following firestore-debug.log

Mar 29, 2022 10:34:11 AM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start
INFO: Started WebSocket server on ws://localhost:54165
API endpoint: http://localhost:9000
If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:

   export FIRESTORE_EMULATOR_HOST=localhost:9000

Dev App Server is now running.

Mar 29, 2022 10:34:16 AM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
Mar 29, 2022 10:38:52 AM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected non-HTTP/2 connection.
Mar 29, 2022 10:38:52 AM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
Mar 29, 2022 10:41:51 AM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected non-HTTP/2 connection.
Mar 29, 2022 10:43:31 AM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
  at java.lang.StringCoding.encode(StringCoding.java:350)
  at java.lang.String.getBytes(String.java:941)
  at com.google.cloud.datastore.core.rep.converter.ConverterHelper.convertStringToBytes(ConverterHelper.java:98)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.addProperty(AppEngV3EntityFromRepConverter.java:65)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.convertMapToEntity(AppEngV3EntityFromRepConverter.java:57)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.convertValue(AppEngV3EntityFromRepConverter.java:192)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.addSingleProperty(AppEngV3EntityFromRepConverter.java:91)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.addProperty(AppEngV3EntityFromRepConverter.java:79)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.convertMapToEntity(AppEngV3EntityFromRepConverter.java:57)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.convertEntity(AppEngV3EntityFromRepConverter.java:35)
  at com.google.cloud.datastore.core.appengv3.converter.AppEngV3EntityFromRepConverter.convertEntityUnchecked(AppEngV3EntityFromRepConverter.java:28)
  at com.google.cloud.datastore.emulator.impl.util.FirestoreEmulatorConverters.entityToProto(FirestoreEmulatorConverters.java:300)
  at com.google.cloud.datastore.emulator.impl.util.FirestoreEmulatorConverters.entityToProto2(FirestoreEmulatorConverters.java:304)
  at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.lambda$exportData$16(CloudFirestoreV1.java:758)
  at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1$$Lambda$1287/780587234.apply(Unknown Source)
  at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
  at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
  at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
  at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
  at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
  at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
  at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
  at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.exportData(CloudFirestoreV1.java:759)
  at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.exportData(CloudFirestoreV1Router.java:215)
  at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1.lambda$exportData$3(EmulatorAuxiliaryGrpcAdapter.java:98)
  at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1$$Lambda$1282/1298309044.process(Unknown Source)
  at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter.unary(EmulatorAuxiliaryGrpcAdapter.java:49)
  at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter.access$000(EmulatorAuxiliaryGrpcAdapter.java:28)
  at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1.exportData(EmulatorAuxiliaryGrpcAdapter.java:95)
  at com.google.firestore.emulator.v1.FirestoreEmulatorGrpc$MethodHandlers.invoke(FirestoreEmulatorGrpc.java:631)
  at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
  at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)

Mar 29, 2022 10:43:31 AM io.gapi.emulators.netty.HttpHandler$1 onError
INFO: Exception when handling request: UNKNOWN

@yuchenshi
Copy link
Member

@jakeleventhal May I ask if you've tried with the memory flags? If so, how much heap space did you start it with?

@jakeleventhal
Copy link

jakeleventhal commented Apr 7, 2022

@yuchenshi i tried with memory flags and per "Activity Monitor" on mac java was only using <1gb ram. i am actually now unable to test this in a timely manner perhaps because of some other bug. In the for loop for my script, the first ~3,000 iterations were lightning fast (>100/s) but once it gets to ~3200 it slows to a crawl. Each iteration of the loop where i console.log(i) takes about 2-5 seconds. And then eventually it crashes with a "DEADLINE_EXCEEDED" error even though it is just the local emulator. I think what I provided is enough for a minimal reproduction case. FWIW i am running on a M1 chip not intel

@AndreasJJ
Copy link

AndreasJJ commented Apr 11, 2022

Edit: It feels like there's a certain limit around those 4.6MB that makes it crash as simply editing some (small) field values, so adding a few bytes can make the difference between it not failing and failing. This is just an empiric observation though.

I am having the same problem (with the exact same stacktrace of java.nio.BufferOverflowException) while exporting as little as 4.6MB data (4 650 078 bytes of total export data, and 4 611 495 bytes of firestore export data). My dataset is very small and probably contains less than 100 documents, but some of the documents got fields that can be upwards of 700KB.

OS: MacOS 11.5.2 (16GB ram)
Firebase tools: 10.6.0

@joehan
Copy link
Contributor

joehan commented Apr 11, 2022

@AndreasJJ Would you be able to provide a repro for that BufferOverflowException? This would help the Firestore team identify what's going wrong here.

Additionally, are you using a Mac with Intel chips or an M1 Mac?

@AndreasJJ
Copy link

AndreasJJ commented Apr 11, 2022

@joehan

I am using a Intel chip Mac.

So i tried to create a new repo for repro, where i simply copied the entire firebase folder into the new repo. In addition to changing the project id to a new project (as i didnt want my original project id to be shown in a public repo). However trying to edit the dataset in the new repo (which should have the exact same state as the one throwing the BufferOverflowException) doesn't end with an export error. As such i wonder if the error might have something to do with whatever files and states firebase saves locally on my computer that is associated with my original project id.

Just for reference, here's the original error from the log from my real repo when i try to export through firebase emulators:start --import test_data --export-on-exit.

INFO: Detected non-HTTP/2 connection.
Apr 11, 2022 11:10:16 PM com.google.cloud.datastore.emulator.impl.util.WrappedStreamObserver onError
INFO: operation failed: null
java.nio.BufferOverflowException
	at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:213)
	at com.google.cloud.datastore.util.leveldb.LevelDBLogWriterChannel.writePhysicalRecord(LevelDBLogWriterChannel.java:154)
	at com.google.cloud.datastore.util.leveldb.LevelDBLogWriterChannel.write(LevelDBLogWriterChannel.java:77)
	at com.google.cloud.datastore.util.leveldb.LevelDBLogWriterChannel.write(LevelDBLogWriterChannel.java:56)
	at com.google.cloud.datastore.util.leveldb.ExportImportUtil.writeEntitiesToFile(ExportImportUtil.java:183)
	at com.google.cloud.datastore.util.leveldb.ExportImportUtil.exportEntitiesForSpec(ExportImportUtil.java:158)
	at com.google.cloud.datastore.util.leveldb.ExportImportUtil.exportEntities(ExportImportUtil.java:90)
	at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1.exportData(CloudFirestoreV1.java:763)
	at com.google.cloud.datastore.emulator.impl.CloudFirestoreV1Router.exportData(CloudFirestoreV1Router.java:215)
	at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1.lambda$exportData$3(EmulatorAuxiliaryGrpcAdapter.java:98)
	at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter.unary(EmulatorAuxiliaryGrpcAdapter.java:49)
	at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter.access$000(EmulatorAuxiliaryGrpcAdapter.java:28)
	at com.google.cloud.datastore.emulator.firestore.EmulatorAuxiliaryGrpcAdapter$1.exportData(EmulatorAuxiliaryGrpcAdapter.java:95)
	at com.google.firestore.emulator.v1.FirestoreEmulatorGrpc$MethodHandlers.invoke(FirestoreEmulatorGrpc.java:631)
	at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
	at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
	at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
	at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
	at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
	at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
	at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
	at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
	at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:340)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:866)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

Apr 11, 2022 11:10:16 PM io.gapi.emulators.netty.HttpHandler$1 onError
INFO: Exception when handling request: UNKNOWN
*** shutting down gRPC server since JVM is shutting down
*** server shut down

@jakeleventhal
Copy link

@joehan @yuchenshi i am using m1 mac

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants