[
https://issues.apache.org/jira/browse/CASSANDRA-6574?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13880372#comment-13880372
]
Chris Burroughs commented on CASSANDRA-6574:
--------------------------------------------
So with CASSANDRA-6591 I'm not as sure about the changes to the hit rate, I'll
need to wait to gather more data on that.
I tried counting how many times AutoSavingCache got null, and the answer is
often. I suspected it would be due to the so called "harmless" errors but did
not catch any. I forgot to instrument `deserialize` itself so I'm not sure if
it's because the reader is null (I assume that means the sstable does not
exist) as was suggested or something else.
{noformat}
[host20] out: INFO [main] 2014-01-23 07:20:01,560 AutoSavingCache.java (line
172) completed reading (992 ms; 262541 keys; 112683 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf
[host21] out: INFO [main] 2014-01-23 07:30:20,359 AutoSavingCache.java (line
172) completed reading (902 ms; 249105 keys; 131675 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host22] out: INFO [main] 2014-01-23 07:33:40,099 AutoSavingCache.java (line
172) completed reading (942 ms; 279683 keys; 103318 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host24] out: INFO [main] 2014-01-23 07:44:22,949 AutoSavingCache.java (line
172) completed reading (933 ms; 263067 keys; 114736 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host25] out: INFO [main] 2014-01-23 07:57:18,383 AutoSavingCache.java (line
172) completed reading (897 ms; 253704 keys; 124060 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host26] out: INFO [main] 2014-01-23 08:11:22,907 AutoSavingCache.java (line
172) completed reading (936 ms; 218463 keys; 167920 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host27] out: INFO [main] 2014-01-23 08:19:58,702 AutoSavingCache.java (line
172) completed reading (702 ms; 94469 keys; 218068 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host28] out: INFO [main] 2014-01-23 08:28:53,980 AutoSavingCache.java (line
172) completed reading (1466 ms; 275006 keys; 105317 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host2c] out: INFO [main] 2014-01-23 08:39:33,963 AutoSavingCache.java (line
172) completed reading (902 ms; 251710 keys; 124851 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host2e] out: INFO [main] 2014-01-23 08:50:12,532 AutoSavingCache.java (line
172) completed reading (1131 ms; 109189 keys; 279056 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host30] out: INFO [main] 2014-01-23 09:16:34,146 AutoSavingCache.java (line
172) completed reading (1255 ms; 207669 keys; 178634 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host31] out: INFO [main] 2014-01-23 09:23:29,407 AutoSavingCache.java (line
172) completed reading (910 ms; 212988 keys; 178641 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host33] out: INFO [main] 2014-01-23 09:37:02,292 AutoSavingCache.java (line
172) completed reading (809 ms; 125849 keys; 258488 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host34] out: INFO [main] 2014-01-23 09:46:12,921 AutoSavingCache.java (line
172) completed reading (787 ms; 141332 keys; 143669 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host35] out: INFO [main] 2014-01-23 09:56:48,539 AutoSavingCache.java (line
172) completed reading (1188 ms; 278307 keys; 99655 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host36] out: INFO [main] 2014-01-23 10:03:17,176 AutoSavingCache.java (line
172) completed reading (1005 ms; 115305 keys; 275064 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host38] out: INFO [main] 2014-01-23 10:22:17,540 AutoSavingCache.java (line
172) completed reading (948 ms; 202602 keys; 187670 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host39] out: INFO [main] 2014-01-23 10:32:03,239 AutoSavingCache.java (line
172) completed reading (1124 ms; 255997 keys; 122733 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host3b] out: INFO [main] 2014-01-23 11:37:58,022 AutoSavingCache.java (line
172) completed reading (1381 ms; 270863 keys; 106745 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host3d] out: INFO [main] 2014-01-23 11:51:52,110 AutoSavingCache.java (line
172) completed reading (803 ms; 144620 keys; 241353 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host43] out: INFO [main] 2014-01-23 12:10:36,612 AutoSavingCache.java (line
172) completed reading (814 ms; 188137 keys; 193903 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host44] out: INFO [main] 2014-01-23 12:23:04,071 AutoSavingCache.java (line
172) completed reading (910 ms; 170228 keys; 218621 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host46] out: INFO [main] 2014-01-23 12:35:53,145 AutoSavingCache.java (line
172) completed reading (1421 ms; 278143 keys; 101378 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host48] out: INFO [main] 2014-01-23 12:59:53,077 AutoSavingCache.java (line
172) completed reading (1307 ms; 251622 keys; 125019 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host11] out: INFO [main] 2014-01-23 13:19:08,074 AutoSavingCache.java (line
172) completed reading (1585 ms; 164143 keys; 217761 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host12] out: INFO [main] 2014-01-23 13:32:36,866 AutoSavingCache.java (line
172) completed reading (891 ms; 255190 keys; 122579 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host13] out: INFO [main] 2014-01-23 13:46:03,430 AutoSavingCache.java (line
172) completed reading (1371 ms; 249164 keys; 133814 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host15] out: INFO [main] 2014-01-23 14:14:55,300 AutoSavingCache.java (line
172) completed reading (1325 ms; 202864 keys; 175770 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host16] out: INFO [main] 2014-01-23 14:28:45,457 AutoSavingCache.java (line
172) completed reading (712 ms; 107782 keys; 278634 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host18] out: INFO [main] 2014-01-23 14:44:28,201 AutoSavingCache.java (line
172) completed reading (800 ms; 150054 keys; 230031 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host29] out: INFO [main] 2014-01-23 14:57:37,723 AutoSavingCache.java (line
172) completed reading (819 ms; 78052 keys; 287925 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
[host10] out: INFO [main] 2014-01-23 15:10:57,116 AutoSavingCache.java (line
172) completed reading (910 ms; 72719 keys; 315142 null) saved cache
/home/cassandra/shared/saved_caches/ks-cf-KeyCache-b.db
{noformat}
> key cache shrinks on restart
> ----------------------------
>
> Key: CASSANDRA-6574
> URL: https://issues.apache.org/jira/browse/CASSANDRA-6574
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Environment: 1.2.12 + patches
> Reporter: Chris Burroughs
> Attachments: key-cache-entries.png, key-cache-rate.png
>
>
> During a rolling restart the key number of entries the number of entries in
> the key cache is shrinking. That is far fewer entries are loaded than are
> saved. This has obvious bad consequences for post restart performance.
> {noformat}
> key_cache_size_in_mb: 48
> key_cache_save_period: 900
> # Number of keys from the key cache to save
> # Disabled by default, meaning all keys are going to be saved
> # key_cache_keys_to_save: 100
> row_cache_size_in_mb: 256
> row_cache_save_period: 300
> row_cache_keys_to_save: 50000
> row_cache_provider: SerializingCacheProvider
> saved_caches_directory: /home/cassandra/shared/saved_caches
> {noformat}
> Same log lines:
> {noformat}
> INFO [CompactionExecutor:24543] 2014-01-11 11:35:47,783 AutoSavingCache.java
> (line 289) Saved KeyCache (398028 items) in 1252 ms
> *** RESTART ***
> INFO [main] 2014-01-11 11:44:59,608 AutoSavingCache.java (line 140) reading
> saved cache /home/cassandra/shared/saved_caches/ks-cf1-KeyCache-b.db
> INFO [main] 2014-01-11 11:45:00,509 AutoSavingCache.java (line 140) reading
> saved cache /home/cassandra/shared/saved_caches/ks-cf2-RowCache-b.db
> INFO [main] 2014-01-11 12:02:48,675 ColumnFamilyStore.java (line 452)
> completed loading (1068166 ms; 50000 keys) row cache for ks.cf2
> INFO [main] 2014-01-11 12:02:48,769 CassandraDaemon.java (line 291)
> completed pre-loading (67760 keys) key cache.
> INFO [main] 2014-01-11 12:02:48,769 CassandraDaemon.java (line 294)
> completed pre-loading (50000 keys) row cache.
> INFO [CompactionExecutor:1] 2014-01-11 12:02:49,133 AutoSavingCache.java
> (line 289) Saved RowCache (50000 items) in 266 ms
> INFO [CompactionExecutor:2] 2014-01-11 12:02:49,575 AutoSavingCache.java
> (line 289) Saved KeyCache (67760 items) in 707 ms
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
