Large latency on Tensor allocation

[nebulorum]

System information

• TensorFlow version: 0.3.1
• Doc Link: https://www.tensorflow.org/jvm/install

Describe the documentation issue

Not sure this is the correct forum but I would like to some guidance on how to setup sessions and resource management would be interesting.

After two weeks trying to understand why latencies in 0.3.1 were completely uncontrollable (as compared to official 1.3.1) I ran into #208. This matches my observations.

We are trying to run Prediction on models with thousands of data points in different tensor per prediction. Memory allocation on the threads are in 20MB/s and there seems to be a sync between JavaCCP Allocation thread and our worker threads. In addition to this allocation using Size(1) tensor seems to be very slow (in the 7ms range).

After reading #208, it seems we are doing everything wrong. But I don't really have a clear picture of how it should be done: Would EagerSession help? Could I use a Session per HTTP request? Should I allocate larger multi-dimensional tensors instead of a single one? How should I configure thread pools? I understand that the API is work in progress, but current documentation is very light on this kind of documentation.

I don't think this is a bug, but I can convert into some other sort of issue.

[Craigacp]

Session should be long lived as recreating it involves a bunch of allocations and other things. If you can batch up the incoming requests then that will allow the TF native runtime to perform more efficient batched matrix multiplies/convolutions (in many cases). I think the Session object should be thread safe so you can use it concurrently from multiple threads.

We should probably turn off the JavaCPP memory allocation size check and let the GC clear it up, if you're creating lots of Java side objects GC should run frequently enough to clear things out anyway. Are you hitting the thread.sleep inside JavaCPP's allocator?

Note if you're making lots of sessions out of saved model bundles you might be hitting some memory leaks inside TF's C API (which the TF Java API uses to interact with the native library). I opened this issue (tensorflow/tensorflow#48802) upstream but we've not had a response yet.

[nebulorum]

Running the JVM under the profiler I never see the JavaCCP deallocation thread sleep. It is either in wait, monitor or running state. On lower load most of the time on wait and then monitor/running sync up with the worker threads.

We have a simple model, that can run in 3ms under low load. Our overall call should happen under 40ms, but when load increases we can clearly see waits in our telemetry. Model evaluation is still quick but something is causing contention on the JVM.

After reviewing the Tensor construction it seems for each request we have 80 Tensor with length 200, some String, most Long. Our feature mapping maybe be generating too much garbage on the side, but after running for a about ~2% of head is org.bytedeco.javacpp.Pointer$DeallocatorReference and another ~2% org.tensorflow.internal.c_api.AbstractTF_Tensor$DeleteDeallocator.

We also see contention on the JavaCCP Deallocation thread. It is the yellow thread on the picture below. Other threads are some of our worker threads:

You can see clearly see several threads block up on a monitor. The image bellow shows that this sync pattern happens more often:

After reviewing some of our thread dumps we also see thread blocking like this:

java.lang.Thread.State: BLOCKED (on object monitor)
	at org.bytedeco.javacpp.Pointer.deallocator(Pointer.java:666)
	- waiting to lock <0x00000005330184f8> (a java.lang.Class for org.bytedeco.javacpp.Pointer$DeallocatorThread)
	at org.bytedeco.javacpp.Pointer.init(Pointer.java:127)
	at org.bytedeco.javacpp.BytePointer.allocateArray(Native Method)
	at org.bytedeco.javacpp.BytePointer.<init>(BytePointer.java:124)
	at org.bytedeco.javacpp.BytePointer.<init>(BytePointer.java:97)
	at org.tensorflow.internal.buffer.ByteSequenceTensorBuffer$InitDataWriter.writeNext(ByteSequenceTensorBuffer.java:129)

Or:

at org.bytedeco.javacpp.Pointer.physicalBytes(Native Method)
	at org.bytedeco.javacpp.Pointer.deallocator(Pointer.java:665)
	at org.tensorflow.internal.c_api.AbstractTF_Tensor.allocateTensor(AbstractTF_Tensor.java:91)
	at org.tensorflow.RawTensor.allocate(RawTensor.java:197)

org.bytedeco.javacpp.Pointer

Looking at org.bytedeco.javacpp.Pointer.java:666 we can see its a synchronized block. And the Pointer has several sync blocks when adding and removing deallocators. I suspect that as 200 requests per second come in, each allocating 80 tensors, we run into contention on the JavaCCP thread, and that causes the sync on monitor and blows our latency through the roof. This does not happen like this in the 1.3.1 library, but we wanted to move to 2.4.1.

I now question if this is a documentation issue, a usage issue or a bug/feature issue. And how to work around this behaviour.

[saudet]

@nebulorum If you see some output when running your app with something like shown at #251 (comment), then it means you're forgetting to call close() on those objects. You'll need to make sure to call close() on those objects to avoid incurring these costs associated with GC fallback. In other words, if you call close() everywhere you can, you will not see any overhead. That responsibility is on you! This has nothing to do with JavaCPP. It is only trying to cope with code that isn't properly calling close() at all the appropriate places. The close() method is a standard Java SE method of the AutoCloseable class. I do not see the point of writing additional documentation about that.

[Craigacp]

The synchronized block in Pointer is going to cause contention on the thread, especially if you're allocating from different threads on different CPUs (or worse still sockets) as it'll cause the object to bounce around. I'm not sure that 200 requests per second is enough to trigger real issues there, but the fact that the Pointer is using a linked list (which is also not particularly multicore friendly) could also be causing trouble. What's the execution environment like (e.g. num CPUs, type of CPUs, num NUMA nodes, is the JVM restricted to a subset thereof)?

[nebulorum]

The synchronized block in Pointer is going to cause contention on the thread, especially if you're allocating from different threads on different CPUs (or worse still sockets) as it'll cause the object to bounce around. I'm not sure that 200 requests per second is enough to trigger real issues there, but the fact that the Pointer is using a linked list (which is also not particularly multicore friendly) could also be causing trouble. What's the execution environment like (e.g. num CPUs, num NUMA nodes, is the JVM restricted to a subset thereof)?

We are running on AWS only CPU, no co-processors. What has baffled us it that 1.3.1 has very stable latency and the code is 3 year old. This new endpoint can be faster, but degrades really quickly as load increases.

I have considered having a Tensor allocating thread so that we have fewer thread fighting for the block. But this will obviously create a bottleneck.

[karllessard]

@saudet , if I understand correctly, this synchronization will happen every time a resource is deallocated, no matter if the allocated memory is getting high or not. It would be interesting to disable completely the feature where JavaCPP keeps track of the amount of memory allocated and avoid this thread locking (looks like it is not avoidable here, even if you set maxPhysicalBytes, maxRetries or maxBytes to 0).

Since that's a protected method, I can override it and run a test to see if there is any gain. @nebulorum , do you have any code available to share to run this benchmark?

[Craigacp]

The synchronized block in Pointer is going to cause contention on the thread, especially if you're allocating from different threads on different CPUs (or worse still sockets) as it'll cause the object to bounce around. I'm not sure that 200 requests per second is enough to trigger real issues there, but the fact that the Pointer is using a linked list (which is also not particularly multicore friendly) could also be causing trouble. What's the execution environment like (e.g. num CPUs, num NUMA nodes, is the JVM restricted to a subset thereof)?

We are running on AWS only CPU, no co-processors. What has baffled us it that 1.3.1 has very stable latency and the code is 3 year old. This new endpoint can be faster, but degrades really quickly as load increases.

I have considered having a Tensor allocating thread so that we have fewer thread fighting for the block. But this will obviously create a bottleneck.

Ok, how big is your AWS instance? If there are NUMA effects from multiple CPU sockets (or within a socket for some of the AMD EPYC variants) then this could slow things down, and having a single thread doing the input tensor creation would help (though given there are lots of other things that create JavaCPP Pointers during a session.run call it won't prevent everything from bouncing the locking object across sockets).

As Karl says, we should look at this locking on our side to see if we can improve things, but in the meantime pinning the threads if you're on a large machine might help.

[nebulorum]

@nebulorum If you see some output when running your app with something like shown at #251 (comment), then it means you're forgetting to call close() on those objects. You'll need to make sure to call close() on those objects to avoid incurring these costs associated with GC fallback. In other words, if you call close() everywhere you can, you will not see any overhead. That responsibility is on you! This has nothing to do with JavaCPP. It is only trying to cope with code that isn't properly calling close() at all the appropriate places. The close() method is a standard Java SE method of the AutoCloseable class. I do not see the point of writing additional documentation about that.

We checked in integration on if we call gc() in the test we do see the messages as referred on #251. We will try to close all Tensors before leaving the model execution part and see if this improves.

While we did have a face palm moment when you mentioned the AutoClosable, I would however suggest that the example include a dbx.close() in the example.

Making sure people are aware they need to do proper resource management to ensure performance may be helpful. Specially since this is not the first issue around the topic.

[saudet]

@saudet , if I understand correctly, this synchronization will happen every time a resource is deallocated, no matter if the allocated memory is getting high or not. It would be interesting to disable completely the feature where JavaCPP keeps track of the amount of memory allocated and avoid this thread locking (looks like it is not avoidable here, even if you set maxPhysicalBytes, maxRetries or maxBytes to 0).

Sigh... sure, I can probably do that when the "org.bytedeco.javacpp.nopointergc" system property is set to "true" so that you can all stop blaming me for bugs in your code! :) No one has never ever encountered any issues like that with JavaCPP in the past. This is a problem in TF Java.

[Craigacp]

@saudet , if I understand correctly, this synchronization will happen every time a resource is deallocated, no matter if the allocated memory is getting high or not. It would be interesting to disable completely the feature where JavaCPP keeps track of the amount of memory allocated and avoid this thread locking (looks like it is not avoidable here, even if you set maxPhysicalBytes, maxRetries or maxBytes to 0).

Sigh... sure, I can probably do that when the "org.bytedeco.javacpp.nopointergc" system property is set to "true" so that you can all stop blaming me for bugs in your code! :) No one has never ever encountered any issues like that with JavaCPP in the past. This is a problem in TF Java.

Lock contention is a different issue to the freeing of resources. If threads are blocked waiting for the lock on DeallocatorThread or DeallocatorReference (as indicated by the screenshots) then that's a different problem to the leaking of memory from unclosed tensors. How large a machine have you run this on? Using a single lock to guard a resource which is accessed from multiple threads or sockets is going to slow down under contention, the question is just how much contention it takes to cause problems.

[nebulorum]

So we added calling close on all tensors and the number of Pointer$NativeDeallocator went down. But thread sync is still going on and no noticeable impact of latencies.

We are doing this load testing on AWS c5.4xlarge (well the host for are K8S Pods).

One other thing I was considering is preallocating and reusing the Tensor. We could put an upper bound on tensor length and maybe preallocate them. Not sure this would work on the runtime though. And thinking, is a bit optimistic because doing this logic would be hard. Also current implementation has no mutator for the tensors.

[Craigacp]

So we added calling close on all tensors and the number of Pointer$NativeDeallocator went down. But thread sync is still going on and no noticeable impact of latencies.

We are doing this load testing on AWS c5.4xlarge (well the host for are K8S Pods).

One other thing I was considering is preallocating and reusing the Tensor. We could put an upper bound on tensor length and maybe preallocate them. Not sure this would work on the runtime though. And thinking, is a bit optimistic because doing this logic would be hard. Also current implementation has no mutator for the tensors.

You can write values directly into the tensors when they are cast to their appropriate type (e.g. TFloat32 or TUint8). They have set methods inherited from the NdArray subinterface.

A c5.4xlarge shouldn't be big enough to exhibit NUMA effects, as I'd expect it to be on a single socket, so at least it's not that.

[nebulorum]

You can write values directly into the tensors when they are cast to their appropriate type (e.g. TFloat32 or TUint8). They have set methods inherited from the NdArray subinterface.

If I go down this route, is it possible to also update the shape of the Tensor? My thinking is given a modes we know how many tensor, and the maximum size. Allocate the the for the maximum size, set the data update the dimension. Not allocation needed.

[nebulorum]

Tried to work with capacity to see the breaking point.

VU	RPS	p50	p95
300	277	70 ms	180 ms
200	190	40	100
100	97	24	86
50	48	18	37

The composite below show JavaCCP and some of the 32 thread in different load levels (300, 200, 100 VU).

The smaller the load the full column of sync action is less common. At higher load contention looks a lot worst. Not that the window tick on the graph as 2 seconds apart and light blue is state monitor. Event at low loads the sync appear. At 300 VU, K8S reported 6.27 CPUs of usage.

We will try smaller thread pools. But there seems to be some interesting interplay on the JavaCPP thread.