Repository navigation
Large latency on Tensor allocation #313
Description
Activity
Sessionshould 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 theSessionobject 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.
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 Deallocationthread. 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:666we can see its asynchronizedblock. 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 theJavaCCPthread, 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.
@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 callclose()on those objects to avoid incurring these costs associated with GC fallback. In other words, if you callclose()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 callingclose()at all the appropriate places. Theclose()method is a standard Java SE method of theAutoCloseableclass. I do not see the point of writing additional documentation about that.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)?
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.
@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,maxRetriesormaxBytesto 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?
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 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 callclose()on those objects to avoid incurring these costs associated with GC fallback. In other words, if you callclose()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 callingclose()at all the appropriate places. Theclose()method is a standard Java SE method of theAutoCloseableclass. 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 adbx.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.
Reacted by Samuel Audet@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,maxRetriesormaxBytesto 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.
@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,maxRetriesormaxBytesto 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
DeallocatorThreadorDeallocatorReference(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.So we added calling
closeon all tensors and the number ofPointer$NativeDeallocatorwent 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.
So we added calling
closeon all tensors and the number ofPointer$NativeDeallocatorwent 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.
TFloat32orTUint8). They have set methods inherited from theNdArraysubinterface.A
c5.4xlargeshouldn'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.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.
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.
- added a commit that references this issue
on May 5, 2021 17 remaining items
- added a commit that references this issue
on May 9, 2021 We have no TensorFlow specific config or flags, and on Dockerfile we just give some params to the JVM:
java -server -XX:MaxRAMPercentage=70 -XX:InitialRAMPercentage=70 \ -Xlog:gc -XX:MaxGCPauseMillis=20 -XX:+AlwaysPreTouch -XX:+DisableExplicitGC\ -XX:+ExitOnOutOfMemoryError \ -jar /service.jarWhere are you setting the "org.bytedeco.javacpp.nopointergc" system property to "true"?
There's one more place where synchronization could potentially take place when classes are unloaded, for the WeakHashMap used inside the call to sizeof() in Pointer.DeallocatorReference, but I have a hard time imagining in what kind of application that would actually matter. In any case, I've "fixed" that in commit bytedeco/javacpp@0ce97fc .
Where are you setting the "org.bytedeco.javacpp.nopointergc" system property to "true"?
We collected from our production config. If we can run the SNAPSHOT version in production we will do it. We need to release a version of this for some testing.
But this was more to this question:
A mutex does get used here when collecting stats: https://github.com/tensorflow/tensorflow/blob/master/tensorflow/core/framework/cpu_allocator_impl.cc
Are you sure that hasn't been enabled somehow?No I don't know how I would have turned on the Mutex. We are not using any additional configuration. Maybe we should make sure the mutex is not on.
As your example showed if Tensors are not allocated performance is pretty stable. So maybe the issues is not JavaCPP.
- changed the title
[-]Documentation on Session and Resource management[/-][+]Large latency on Tensor allocation[/+]on May 10, 2021 Using TF Java 0.3.1 and JavaCPP 1.5.6-SNAPSHOT with "noPointerGC", the original AllocateStress also looks OK to me:
nAlloc 5621 (total): 5586 (<10ms); 34 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5678 (total): 5668 (<10ms); 10 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5663 (total): 5651 (<10ms); 15 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5720 (total): 5699 (<10ms); 20 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5613 (total): 5601 (<10ms); 11 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5776 (total): 5766 (<10ms); 9 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5640 (total): 5600 (<10ms); 41 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5660 (total): 5650 (<10ms); 13 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5667 (total): 5655 (<10ms); 9 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5627 (total): 5593 (<10ms); 33 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5718 (total): 5706 (<10ms); 12 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5658 (total): 5650 (<10ms); 10 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5638 (total): 5615 (<10ms); 22 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5648 (total): 5631 (<10ms); 27 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5637 (total): 5603 (<10ms); 23 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5640 (total): 5608 (<10ms); 32 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms) nAlloc 5731 (total): 5707 (<10ms); 24 (<20ms); - (<30ms); - (<40ms); - (<50ms); - (<100ms); - (<200ms); - ( >200ms)We collected from our production config. If we can run the SNAPSHOT version in production we will do it. We need to release a version of this for some testing.
If you're satisfied with JavaCPP 1.5.6-SNAPSHOT, but need a release, I can do a 1.5.5-1 or something with the fix, but before doing that please make sure that there isn't something else that you may want updated as well. Thanks for testing!
We ran this (better @dennisTS did) in our test rig and things improved a lot:
600 RPS against 8CPU we are getting p99.9 =48ms and p95 = 24ms
So real improvement using this version and option.
As a follow-up what do we lose by using
nopointergc?Reacted by Samuel AudetJavaCPP GC thread is mostly useful to collect unclosed resources in eager mode, which is mostly used for debugging than for high-performance in production. If you are running sessions from a saved model graph, you normally don't need an eager session and can live with
nopointergcwithout issue.@saudet , is there a way to completely turn off GC support in JavaCPP programmatically instead of passing a parameter to the command line? I guess we can define the value for this environment variable directly in TF Java before loading the TensorFlow runtime library but how to guarantee we can do it before JavaCPP libraries statically loads up?
Now that we've been running for some hours in test we would really like to release to production. Will check with security if we can use the snapshot. But how long would it take to release a version of JavaCPP?
@saudet , is there a way to completely turn off GC support in JavaCPP programmatically instead of passing a parameter to the command line? I guess we can define the value for this environment variable directly in TF Java before loading the TensorFlow runtime library but how to guarantee we can do it before JavaCPP libraries statically loads up?
Not really possible, unless TF Java is the only library using JavaCPP in the app, and if the user has other libraries using JavaCPP, it's probably not a good idea to tamper with global settings like that anyway. In any case, this is the kind of information that is useful for optimization, and should be part of the documentation on a page, for example, like those here:
https://deeplearning4j.konduit.ai/config/config-memory
https://netty.io/wiki/reference-counted-objects.htmlThat said, I could add a parameter to
Pointer.deallocator()that would let users specify whether they want to keep it out of the reference queue or not. The deallocator thread would still be there by default, but wouldn't do anything.Now that we've been running for some hours in test we would really like to release to production. Will check with security if we can use the snapshot. But how long would it take to release a version of JavaCPP?
A couple of days, but like I said, let's make sure there isn't anything else we want to put in there...
We've been running the SNAPSHOT for some days and it seems OK. Did the final version get release?
We've been running the SNAPSHOT for some days and it seems OK. Did the final version get release?
You mean JavaCPP? No, do you need one?
BTW, latency may be potentially even lower with TF Lite, so if your models are compatible with it, please give it a try:
Those are currently wrappers for the C++ API, but if you would like to use an idiomatic high-level API instead, please let us know!
@saudet, sorry for getting back to you with such a delay - somehow forgot about this thread
You mean JavaCPP? No, do you need one?
Well, it would be nice - using SNAPSHOT in production just doesn't feel good :)
BTW, latency may be potentially even lower with TF Lite, so if your models are compatible with it, please give it a try:
We are using higher level APIs now; but generally even with the SNAPSHOT version of JavaCPP latencies are good for us
Reacted by Samuel Audet
System information
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
EagerSessionhelp? Could I use aSessionper 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.