I would like to thanks for all work done on this rock db based state lookup. Its greate saviour. In our system we use state store for deduplication work and unique grows to more than 100 millions. I see it runs smoothly for some good no of batches but after that lot of gc starts happening and then container gets killed.
Any suggestion to come out of this problem
Below is some lines from log
2020-09-01 06:08:05,418 INFO org.apache.spark.executor.Executor:57 - Running task 7.1 in stage 280.0 (TID 452466)
2020-09-01 06:08:05,446 INFO org.apache.spark.executor.Executor:57 - Fetching spark://gpm302.sjc2.asn.net:42759/jars/flowlog-experiment.jar with timestamp 1598925065034
2020-09-01 06:08:05,471 INFO org.apache.spark.network.client.TransportClientFactory:272 - Successfully created connection to gpm302.sjc2.asn.net/10.0.1.171:42759 after 1 ms (0 ms spent in bootstraps)
2020-09-01 06:08:05,475 INFO org.apache.spark.util.Utils:57 - Fetching spark://gpm302.sjc2.asn.net:42759/jars/flowlog-experiment.jar to /data1/yarn/nm/usercache/root/appcache/application_1597935678144_0210/spark-44780dbc-a224-4c07-bd5c-537db7f7df45/fetchFileTemp490451002513480794.tmp
2020-09-01 06:08:05,580 INFO org.apache.spark.util.Utils:57 - Copying /data1/yarn/nm/usercache/root/appcache/application_1597935678144_0210/spark-44780dbc-a224-4c07-bd5c-537db7f7df45/420339351598925065034_cache to /data2/yarn/nm/usercache/root/appcache/application_1597935678144_0210/container_1597935678144_0210_01_004469/./flowlog-experiment.jar
2020-09-01 06:08:05,590 INFO org.apache.spark.executor.Executor:57 - Adding file:/data2/yarn/nm/usercache/root/appcache/application_1597935678144_0210/container_1597935678144_0210_01_004469/./flowlog-experiment.jar to class loader
2020-09-01 06:08:05,614 INFO org.apache.spark.MapOutputTrackerWorker:57 - Updating epoch to 182 and clearing cache
2020-09-01 06:08:05,668 INFO org.apache.spark.broadcast.TorrentBroadcast:57 - Started reading broadcast variable 455
2020-09-01 06:08:05,746 INFO org.apache.spark.network.client.TransportClientFactory:272 - Successfully created connection to gpm403.sjc2.asn.net/10.0.1.215:34457 after 2 ms (0 ms spent in bootstraps)
2020-09-01 06:08:05,776 INFO org.apache.spark.storage.memory.MemoryStore:57 - Block broadcast_455_piece0 stored as bytes in memory (estimated size 59.8 KB, free 486.1 MB)
2020-09-01 06:08:05,816 INFO org.apache.spark.broadcast.TorrentBroadcast:57 - Reading broadcast variable 455 took 148 ms
2020-09-01 06:08:06,150 INFO org.apache.spark.storage.memory.MemoryStore:57 - Block broadcast_455 stored as values in memory (estimated size 195.8 KB, free 486.0 MB)
3.780: [GC (Metadata GC Threshold) 3.839: [SoftReference, 0 refs, 0.0000340 secs]3.840: [WeakReference, 424 refs, 0.0001105 secs]3.840: [FinalReference, 3790 refs, 0.0073865 secs]3.847: [PhantomReference, 0 refs, 7 refs, 0.0000188 secs]3.847: [JNI Weak Reference, 0.0000132 secs]AdaptiveSizePolicy::update_averages: survived: 64982432 promoted: 427728 overflow: true
AdaptiveSizeStart: 3.848 collection: 4
PSAdaptiveSizePolicy::compute_eden_space_size limits: desired_eden_size: 1316299653 old_eden_size: 943718400 eden_limit: 943718400 cur_eden: 780140544 max_eden_size: 943718400 avg_young_live: 38897008
PSAdaptiveSizePolicy::compute_eden_space_size: costs minor_time: 0.078534 major_cost: 0.035737 mutator_cost: 0.885729 throughput_goal: 0.990000 live_space: 346373984 free_space: 1438646272 old_eden_size: 943718400 desired_eden_size: 943718400
AdaptiveSizePolicy::survivor space sizes: collection: 4 (65011712, 65011712) -> (65011712, 65011712)
AdaptiveSizeStop: collection: 4
[PSYoungGen: 397975K->63459K(825344K)] 436102K->102003K(1347072K), 0.0689854 secs] [Times: user=0.26 sys=0.02, real=0.07 secs]
3.849: [Full GC (Metadata GC Threshold) 3.855: [SoftReference, 0 refs, 0.0000431 secs]3.855: [WeakReference, 207 refs, 0.0000364 secs]3.855: [FinalReference, 120 refs, 0.0000233 secs]3.855: [PhantomReference, 0 refs, 8 refs, 0.0000136 secs]3.855: [JNI Weak Reference, 0.0000149 secs]AdaptiveSizeStart: 3.917 collection: 5
PSAdaptiveSizePolicy::compute_eden_space_size limits: desired_eden_size: 1306004136 old_eden_size: 943718400 eden_limit: 943718400 cur_eden: 780140544 max_eden_size: 943718400 avg_young_live: 31117606
PSAdaptiveSizePolicy::compute_eden_space_size: costs minor_time: 0.078534 major_cost: 0.037974 mutator_cost: 0.883492 throughput_goal: 0.990000 live_space: 338594560 free_space: 1438646272 old_eden_size: 943718400 desired_eden_size: 943718400
PSAdaptiveSizePolicy::compute_old_gen_free_space: costs minor_time: 0.078534 major_cost: 0.037974 mutator_cost: 0.883492 throughput_goal: 0.990000 live_space: 370662912 free_space: 1438646272 old_promo_size: 494927872 desired_promo_size: 656408576
AdaptiveSizePolicy::old generation size: collection: 5 (534249472) -> (760217600)
AdaptiveSizeStop: collection: 5
[PSYoungGen: 63459K->0K(825344K)] [ParOldGen: 38544K->100759K(742400K)] 102003K->100759K(1567744K), [Metaspace: 34681K->34681K(1079296K)], 0.0684949 secs] [Times: user=0.32 sys=0.03, real=0.07 secs]
2020-09-01 06:08:06,710 INFO org.apache.spark.broadcast.TorrentBroadcast:57 - Started reading broadcast variable 453
2020-09-01 06:08:06,727 INFO org.apache.spark.network.client.TransportClientFactory:272 - Successfully created connection to gpm403.sjc2.asn.net/10.0.1.215:36054 after 0 ms (0 ms spent in bootstraps)
2020-09-01 06:08:06,735 INFO org.apache.spark.storage.memory.MemoryStore:57 - Block broadcast_453_piece0 stored as bytes in memory (estimated size 32.8 KB, free 485.9 MB)
2020-09-01 06:08:06,763 INFO org.apache.spark.broadcast.TorrentBroadcast:57 - Reading broadcast variable 453 took 52 ms
2020-09-01 06:08:06,842 INFO org.apache.spark.storage.memory.MemoryStore:57 - Block broadcast_453 stored as values in memory (estimated size 441.5 KB, free 485.5 MB)
2020-09-01 06:08:06,847 INFO org.apache.spark.sql.execution.streaming.state.StateStore:57 - State Store maintenance task started
2020-09-01 06:08:07,603 INFO org.apache.spark.sql.execution.streaming.state.StateStore:57 - Retrieved reference to StateStoreCoordinator: org.apache.spark.sql.execution.streaming.state.StateStoreCoordinatorRef@1788d316
2020-09-01 06:08:07,609 INFO org.apache.spark.sql.execution.streaming.state.StateStore:57 - Reported that the loaded instance StateStoreProviderId(StateStoreId(hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state,0,7,default),bb567619-96dd-4f9d-bfb4-1ee530bc0772) is active
2020-09-01 06:08:07,610 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - get Store for version 44
2020-09-01 06:08:07,616 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Loading state into the db for 44 and partition 7
2020-09-01 06:08:07,752 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Will download hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/33.snapshot at location file:/data1/rock/tmp/state_-191076869/0/7/33.tar
2020-09-01 06:08:10,111 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/34.delta
2020-09-01 06:08:10,912 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/35.delta
2020-09-01 06:08:11,696 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/36.delta
2020-09-01 06:08:12,247 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/37.delta
9.746: [GC (Allocation Failure) 9.752: [SoftReference, 0 refs, 0.0000507 secs]9.752: [WeakReference, 120 refs, 0.0000483 secs]9.753: [FinalReference, 4223 refs, 0.0066288 secs]9.759: [PhantomReference, 0 refs, 5 refs, 0.0000135 secs]9.759: [JNI Weak Reference, 0.0000095 secs]AdaptiveSizePolicy::update_averages: survived: 14827544 promoted: 8192 overflow: false
AdaptiveSizeStart: 9.760 collection: 6
PSAdaptiveSizePolicy::compute_eden_space_size limits: desired_eden_size: 1256291548 old_eden_size: 943718400 eden_limit: 943718400 cur_eden: 780140544 max_eden_size: 943718400 avg_young_live: 28511196
PSAdaptiveSizePolicy::compute_eden_space_size: costs minor_time: 0.059481 major_cost: 0.037974 mutator_cost: 0.902545 throughput_goal: 0.990000 live_space: 368056512 free_space: 1600126976 old_eden_size: 943718400 desired_eden_size: 943718400
AdaptiveSizePolicy::survivor space sizes: collection: 6 (65011712, 65011712) -> (65011712, 65011712)
AdaptiveSizeStop: collection: 6
[PSYoungGen: 761856K->14480K(985088K)] 862615K->115247K(1727488K), 0.0140488 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
2020-09-01 06:08:13,177 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/38.delta
2020-09-01 06:08:13,812 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/39.delta
2020-09-01 06:08:15,667 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/40.delta
2020-09-01 06:08:16,221 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/41.delta
2020-09-01 06:08:17,563 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/42.delta
2020-09-01 06:08:18,363 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/43.delta
19.688: [GC (Allocation Failure) 19.692: [SoftReference, 0 refs, 0.0000358 secs]19.692: [WeakReference, 129 refs, 0.0000321 secs]19.692: [FinalReference, 193 refs, 0.0002764 secs]19.692: [PhantomReference, 0 refs, 7 refs, 0.0000168 secs]19.692: [JNI Weak Reference, 0.0000128 secs]AdaptiveSizePolicy::update_averages: survived: 4684216 promoted: 8192 overflow: false
AdaptiveSizeStart: 19.693 collection: 7
avg_survived_padded_avg: 81432944.000000 avg_promoted_padded_avg: 375078.312500 avg_pretenured_padded_avg: 0.000000 tenuring_thresh: 6 target_size: 81788928
PSAdaptiveSizePolicy::compute_eden_space_size limits: desired_eden_size: 1454189753 old_eden_size: 943718400 eden_limit: 943718400 cur_eden: 943718400 max_eden_size: 943718400 avg_young_live: 25175418
PSAdaptiveSizePolicy::compute_eden_space_size: costs minor_time: 0.044743 major_cost: 0.037974 mutator_cost: 0.917283 throughput_goal: 0.990000 live_space: 364720704 free_space: 1600126976 old_eden_size: 943718400 desired_eden_size: 943718400
AdaptiveSizePolicy::survivor space sizes: collection: 7 (65011712, 65011712) -> (4718592, 81788928)
AdaptiveSizeStop: collection: 7
[PSYoungGen: 936080K->4574K(926208K)] 1036847K->105350K(1668608K), 0.0055100 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2020-09-01 06:08:24,290 INFO org.apache.spark.sql.execution.streaming.state.RocksDbStateStoreProvider:57 - Read delta file for version 44 of RocksDbStateStoreProvider[id = (op=0,part=7),dir = hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7] from hdfs://nos-test5.sjc2.asn.net:8020/user/spark/flowlog/store/chkPoint/delta5_nx/state/0/7/44.delta
2020-09-01 06:08:26,519 ERROR org.apache.spark.executor.CoarseGrainedExecutorBackend:43 - RECEIVED SIGNAL TERM
2020-09-01 06:08:26,523 INFO org.apache.spark.storage.DiskBlockManager:57 - Shutdown hook called
2020-09-01 06:08:26,524 INFO org.apache.spark.util.ShutdownHookManager:57 - Shutdown hook called
2020-09-01 06:08:26,525 INFO org.apache.spark.util.ShutdownHookManager:57 - Deleting directory /data2/yarn/nm/usercache/root/appcache/application_1597935678144_0210/spark-931b8dc9-0ebb-418e-865a-96383367cc33
2020-09-01 06:08:26,528 INFO org.apache.spark.util.ShutdownHookManager:57 - Deleting directory /data3/yarn/nm/usercache/root/appcache/application_1597935678144_0210/spark-ad2cdb9e-7ada-438b-adb6-4897a7866b26
2020-09-01 06:08:26,531 INFO org.apache.spark.util.ShutdownHookManager:57 - Deleting directory /data1/yarn/nm/usercache/root/appcache/application_1597935678144_0210/spark-44780dbc-a224-4c07-bd5c-537db7f7df45
Heap
PSYoungGen total 926208K, used 137479K [0x0000000780000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 921600K, 14% used [0x0000000780000000,0x00000007881ca258,0x00000007b8400000)
from space 4608K, 99% used [0x00000007b8400000,0x00000007b88779b8,0x00000007b8880000)
to space 79872K, 0% used [0x00000007bb200000,0x00000007bb200000,0x00000007c0000000)
ParOldGen total 742400K, used 100775K [0x0000000700000000, 0x000000072d500000, 0x0000000780000000)
object space 742400K, 13% used [0x0000000700000000,0x0000000706269fb8,0x000000072d500000)
Metaspace used 47294K, capacity 48058K, committed 48256K, reserved 1091584K
class space used 6272K, capacity 6446K, committed 6528K, reserved 1048576K