Cassandra 1.2 огромная латентность чтения

Question

Я работаю над кластером 4.11 cassandra 1.2.6 с одним ключевым пространством, коэффициент репликации 2 (3 изначально, но упал до 2) и 10 или около того семейств столбцов. Он запускает Oracle 1.7 jvm. Он содержит множество чтений и записей, причем, вероятно, в два-три раза больше записей, чем указано.

Даже при небольшой нагрузке, я вижу очень большие задержки чтения, и я получаю довольно много тайм-аутов чтения (используя драйвер datastax java). Ниже приведен пример вывода из nodetool cfstats для одного из семейств столбцов:

Column Family: user_scores 
    SSTable count: 1 
    SSTables in each level: [1, 0, 0, 0, 0, 0, 0, 0, 0] 
    Space used (live): 7539098 
    Space used (total): 7549091 
    Number of Keys (estimate): 42112 
    Memtable Columns Count: 2267 
    Memtable Data Size: 1048576 
    Memtable Switch Count: 2 
    Read Count: 2101 
    **Read Latency: 272334.202 ms.** 
    Write Count: 24947 
    Write Latency: NaN ms. 
    Pending Tasks: 0 
    Bloom Filter False Positives: 0 
    Bloom Filter False Ratio: 0.00000 
    Bloom Filter Space Used: 55376 
    Compacted row minimum size: 447 
    Compacted row maximum size: 219342 
    Compacted row mean size: 1051 

, как вы можете видеть, я попытался с помощью стратегии базового уплотнению уровня, чтобы попытаться улучшить чтения латентность, но вы также можете увидеть задержку огромный. Я немного в тупике. У меня был кластер cassandra 1.1.6, прекрасно работающий, но до сих пор не повезло с 1.2.

Кластер работает на виртуальных машинах с 4 процессорами и 7 ГБ оперативной памяти. Дисковод данных настроен как полосатый рейд на 4 диска. Машина, похоже, не связана с IO.

У меня есть довольно ванильная конфигурация со всеми значениями по умолчанию.

Я наблюдаю странное поведение ЦП, когда процессор разгоняется даже при меньшей нагрузке. Иногда я вижу, что работает сжатие, но они нарезаны, поэтому я не думаю, что это преступник.

Я пытаюсь выяснить, куда идти дальше. Любая помощь ценится!

[обновление с помощью rpc_timeout trace] Все еще играет с этим. Вот пример трассировки. Похоже, что шаг слияния слишком длинный.

activity                | timestamp | source  | source_elapsed 
-------------------------------------------------------------------------+--------------+---------------+---------------- 
                 execute_cql3_query | 04:57:18,882 | 100.69.176.51 |    0 
Parsing select * from user_scores where user_id='26257166' LIMIT 10000; | 04:57:18,884 | 100.69.176.51 |   1981 
                 Peparing statement | 04:57:18,885 | 100.69.176.51 |   2997 
         Executing single-partition query on user_scores | 04:57:18,885 | 100.69.176.51 |   3657 
              Acquiring sstable references | 04:57:18,885 | 100.69.176.51 |   3724 
              Merging memtable tombstones | 04:57:18,885 | 100.69.176.51 |   3779 
              Key cache hit for sstable 32 | 04:57:18,886 | 100.69.176.51 |   3910 
          Seeking to partition beginning in data file | 04:57:18,886 | 100.69.176.51 |   3930 
           Merging data from memtables and 1 sstables | 04:57:18,886 | 100.69.176.51 |   4211 
                 Request complete | 04:57:38,891 | 100.69.176.51 |  20009870 

Старые следы ниже:

[новый след] После решения проблемы, отмеченные в журналах, полностью восстановление хранилища данных кластера, я все еще столкнулся с проблемой, хотя это заняло довольно немного длиннее. Вот след я схватился, когда в плохом состоянии:

Трассировка сессия: a6dbefc0-ea49-11e2-84bb-ef447a7d9a48

activity                      | timestamp | source   | source_elapsed 
-------------------------------------------------------------------------------------------------+--------------+----------------+---------------- 
                       execute_cql3_query | 16:48:02,755 | 100.69.196.124 |    0 
                 Parsing select * from user_scores limit 1; | 16:48:02,756 | 100.69.196.124 |   1774 
                       Peparing statement | 16:48:02,759 | 100.69.196.124 |   4006 
                    Determining replicas to query | 16:48:02,759 | 100.69.196.124 |   4286 
                  Enqueuing request to /100.69.176.51 | 16:48:02,763 | 100.69.196.124 |   8849 
                 Sending message to cdb002/100.69.176.51 | 16:48:02,764 | 100.69.196.124 |   9456 
                  Message received from /100.69.196.124 | 16:48:03,449 | 100.69.176.51 |   160 
                  Message received from /100.69.176.51 | 16:48:09,646 | 100.69.196.124 |  6891860 
                 Processing response from /100.69.176.51 | 16:48:09,647 | 100.69.196.124 |  6892426 
Executing seq scan across 1 sstables for [min(-9223372036854775808), min(-9223372036854775808)] | 16:48:10,288 | 100.69.176.51 |  6838754 
                Seeking to partition beginning in data file | 16:48:10,289 | 100.69.176.51 |  6839689 
                   Read 1 live and 0 tombstoned cells | 16:48:10,289 | 100.69.176.51 |  6839927 
                Seeking to partition beginning in data file | 16:48:10,289 | 100.69.176.51 |  6839998 
                   Read 1 live and 0 tombstoned cells | 16:48:10,289 | 100.69.176.51 |  6840082 
                    Scanned 1 rows and matched 1 | 16:48:10,289 | 100.69.176.51 |  6840162 
                  Enqueuing response to /100.69.196.124 | 16:48:10,289 | 100.69.176.51 |  6840229 
                   Sending message to /100.69.196.124 | 16:48:10,299 | 100.69.176.51 |  6850072 
                       Request complete | 16:48:09,648 | 100.69.196.124 |  6893029 

[обновление] Я хотел бы добавить, что все работает только денди с экземпляр сольной кассандры на моем macbook pro. AKA работает на моей машине ... :)

[обновление с данными трассировки]

Вот некоторые данные трассировки. Это из драйвера java. Недостатком является то, что я могу только отслеживать запросы, которые преуспевают. Я делаю это в общей сложности 67 запросов, прежде чем каждый запрос начнет отсчет времени. Странно то, что это не выглядит так плохо. В запросе 68 я больше не получаю ответа, а два из серверов работают горячими.

2013-07-11 02:15:45 STDIO [INFO] *************************************** 
66:Host (queried): cdb003/100.69.198.47 
66:Host (tried): cdb003/100.69.198.47 
66:Trace id: c95e51c0-e9cf-11e2-b9a9-5b3c0946787b 

66:-----------------------------------------------------+--------------+-----------------+-------------- 
66:   Enqueuing data request to /100.69.176.51 | 02:15:42.045 | /100.69.198.47 |   200 
66:   Enqueuing digest request to /100.69.176.51 | 02:15:42.045 | /100.69.198.47 |   265 
66:     Sending message to /100.69.196.124 | 02:15:42.045 | /100.69.198.47 |   570 
66:     Sending message to /100.69.176.51 | 02:15:42.045 | /100.69.198.47 |   574 
66:    Message received from /100.69.176.51 | 02:15:42.107 | /100.69.198.47 |  62492 
66:    Processing response from /100.69.176.51 | 02:15:42.107 | /100.69.198.47 |  62780 
66:    Message received from /100.69.198.47 | 02:15:42.508 | /100.69.196.124 |   31 
66:  Executing single-partition query on user_scores | 02:15:42.508 | /100.69.196.124 |   406 
66:      Acquiring sstable references | 02:15:42.508 | /100.69.196.124 |   473 
66:       Merging memtable tombstones | 02:15:42.508 | /100.69.196.124 |   577 
66:      Key cache hit for sstable 11 | 02:15:42.508 | /100.69.196.124 |   807 
66:   Seeking to partition beginning in data file | 02:15:42.508 | /100.69.196.124 |   849 
66:   Merging data from memtables and 1 sstables | 02:15:42.509 | /100.69.196.124 |   1500 
66:    Message received from /100.69.198.47 | 02:15:43.379 | /100.69.176.51 |   60 
66:  Executing single-partition query on user_scores | 02:15:43.379 | /100.69.176.51 |   399 
66:      Acquiring sstable references | 02:15:43.379 | /100.69.176.51 |   490 
66:       Merging memtable tombstones | 02:15:43.379 | /100.69.176.51 |   593 
66:       Key cache hit for sstable 7 | 02:15:43.380 | /100.69.176.51 |   1098 
66:   Seeking to partition beginning in data file | 02:15:43.380 | /100.69.176.51 |   1141 
66:   Merging data from memtables and 1 sstables | 02:15:43.380 | /100.69.176.51 |   1912 
66:     Read 1 live and 0 tombstoned cells | 02:15:43.438 | /100.69.176.51 |  59094 
66:    Enqueuing response to /100.69.198.47 | 02:15:43.438 | /100.69.176.51 |  59225 
66:     Sending message to /100.69.198.47 | 02:15:43.438 | /100.69.176.51 |  59373 
66:Started at: 02:15:42.04466:Elapsed time in micros: 63105 
2013-07-11 02:15:45 STDIO [INFO] *************************************** 
67:Host (queried): cdb004/100.69.184.134 
67:Host (tried): cdb004/100.69.184.134 
67:Trace id: c9f365d0-e9cf-11e2-a4e5-7f3170333ff5 

67:-----------------------------------------------------+--------------+-----------------+-------------- 
67:    Message received from /100.69.184.134 | 02:15:42.536 | /100.69.198.47 |   36 
67:  Executing single-partition query on user_scores | 02:15:42.536 | /100.69.198.47 |   273 
67:      Acquiring sstable references | 02:15:42.536 | /100.69.198.47 |   311 
67:       Merging memtable tombstones | 02:15:42.536 | /100.69.198.47 |   353 
67:       Key cache hit for sstable 8 | 02:15:42.536 | /100.69.198.47 |   436 
67:   Seeking to partition beginning in data file | 02:15:42.536 | /100.69.198.47 |   455 
67:   Merging data from memtables and 1 sstables | 02:15:42.537 | /100.69.198.47 |   811 
67:     Read 1 live and 0 tombstoned cells | 02:15:42.550 | /100.69.198.47 |  14242 
67:    Enqueuing response to /100.69.184.134 | 02:15:42.550 | /100.69.198.47 |  14456 
67:     Sending message to /100.69.184.134 | 02:15:42.551 | /100.69.198.47 |  14694 
67:   Enqueuing data request to /100.69.198.47 | 02:15:43.021 | /100.69.184.134 |   323 
67:     Sending message to /100.69.198.47 | 02:15:43.021 | /100.69.184.134 |   565 
67:    Message received from /100.69.198.47 | 02:15:43.038 | /100.69.184.134 |  17029 
67:    Processing response from /100.69.198.47 | 02:15:43.038 | /100.69.184.134 |  17230 
67:Started at: 02:15:43.021 
67:Elapsed time in micros: 17622 

А вот след используя cqlsh:

Tracing session: d0f845d0-e9cf-11e2-8882-ef447a7d9a48 

activity                | timestamp | source   | source_elapsed 
-------------------------------------------------------------------------+--------------+----------------+---------------- 
                 execute_cql3_query | 19:15:54,833 | 100.69.196.124 |    0 
Parsing select * from user_scores where user_id='39333433' LIMIT 10000; | 19:15:54,833 | 100.69.196.124 |   103 
                 Peparing statement | 19:15:54,833 | 100.69.196.124 |   455 
         Executing single-partition query on user_scores | 19:15:54,834 | 100.69.196.124 |   1400 
              Acquiring sstable references | 19:15:54,834 | 100.69.196.124 |   1468 
              Merging memtable tombstones | 19:15:54,835 | 100.69.196.124 |   1575 
              Key cache hit for sstable 11 | 19:15:54,835 | 100.69.196.124 |   1780 
          Seeking to partition beginning in data file | 19:15:54,835 | 100.69.196.124 |   1822 
           Merging data from memtables and 1 sstables | 19:15:54,836 | 100.69.196.124 |   2562 
             Read 1 live and 0 tombstoned cells | 19:15:54,838 | 100.69.196.124 |   4808 
                 Request complete | 19:15:54,838 | 100.69.196.124 |   5810 

Answer 1

Похоже, я столкнулся с проблемой производительности с 1.2. К счастью, патч только что был применен к ветке 1.2, поэтому, когда я построил исходник, моя проблема исчезла.

см. https://issues.apache.org/jira/browse/CASSANDRA-5677 для подробного объяснения.

Спасибо всем!

Answer 2

Трассировка кажется, показывает, что большая часть времени делают или ожидания для сетевых операций.Возможно, в вашей сети есть проблемы?

Если только некоторые операции не работают, возможно, у вас есть проблема только с одним из ваших узлов. Когда этот узел не нужен, все работает, но когда это необходимо, все идет плохо. Возможно, стоит посмотреть файлы журнала на других узлах.