Оптимизация производительности

[andyray06/rambler_ru]

Здравствуйте.

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

Если во время снижения производительности прочитать информацию о состоянии сервера, то можно заметить что параметр "Длина очереди событий" (eventQueueLength) достигает довольно высоких значений, в то время как сразу после перезагрузки он был равен 0. Использование памяти находится где-то в пределах 40-70%

Можете посоветовать, каким образом можно определить, что именно является "узким местом"?

[anton_logoyskiy/tibbo_com]

Андрей, добрый день!

Судя по Вашему описанию, есть проблема с БД.
Какую БД вы используете? Размещена ли она на другом физическом сервере?
Я обратил бы внимание на настройки работы AggreGate с базой данных и со стороны БД проверил производительность выполнения запросов AggreGate.

С уважением,
Антон Логойский
Tibbo Systems

[andyray06/rambler_ru]

Здравствуйте, Антон.

Используем MySQL 5.7. БД и AggreGate установлены на одном физическом сервере, но устанавливались раздельно.

Конфигурация MySQL следующая:

Код: Выделить всё

[client]
no-beep

port=3306

[mysql]

default-character-set=utf8


[mysqld]

port=3306

datadir=C:/ProgramData/MySQL/MySQL Server 5.7\Data

character-set-server=utf8

default-storage-engine=INNODB

sql-mode="STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"

log-output=FILE
general-log=0
general_log_file="DIGLETT.log"
slow-query-log=1
slow_query_log_file="DIGLETT-slow.log"
long_query_time=10

log-error="DIGLETT.err"

server-id=1

secure-file-priv="C:/ProgramData/MySQL/MySQL Server 5.7/Uploads"

skip-external-locking
max_connections=1000

query_cache_size = 100M

table_open_cache=2000

tmp_table_size=527M

thread_cache_size = 32

myisam_max_sort_file_size=100G

myisam_sort_buffer_size=2G

key_buffer_size = 384M

read_buffer_size=64K
read_rnd_buffer_size=256K

innodb_flush_log_at_trx_commit = 0

innodb_log_buffer_size = 8M

innodb_buffer_pool_size = 2G

innodb_log_file_size = 500M

innodb_thread_concurrency=13

innodb_autoextend_increment=64

innodb_buffer_pool_instances=8

innodb_concurrency_tickets=5000

innodb_old_blocks_time=1000

innodb_open_files=300

innodb_stats_on_metadata=0

innodb_file_per_table=1

innodb_checksum_algorithm=0

back_log=80

flush_time=0

join_buffer_size=256K

max_allowed_packet = 256M

max_connect_errors=100

open_files_limit=4161

query_cache_type=0

sort_buffer_size=256K

table_definition_cache=1400

binlog_row_event_max_size=8K

sync_master_info=10000

sync_relay_log=10000

sync_relay_log_info=10000

plugin_load="mysqlx"

loose_mysqlx_port=33060
innodb_lock_wait_timeout = 1200


Настройки AggreGate:

AggreGate Config.PNG (116.75 КБ) Просмотров: 33301

Подскажите, как можно проверить производительность выполнения запросов на стороне СУБД?
В логах MySQL есть подобные записи:
InnoDB: page_cleaner: 1000ms intended loop took 4618ms. The settings might not be optimal.

[anton_logoyskiy/tibbo_com]

Андрей, я увидел, что вы используете NoSQL базу данных для хранения событий.
Возможно дело в ней. Какую версию AggreGate Вы используете?

В MySQL можно использовать команду show full processlist или настроить slow query log.
http://dev.mysql.com/doc/refman/5.7/en/ ... slist.html
http://dev.mysql.com/doc/refman/5.7/en/ ... y-log.html

Также можно активировать Performance Schema:
http://dev.mysql.com/doc/refman/5.7/en/ ... start.html

С уважением,
Антон Логойский
Tibbo Systems

[andyray06/rambler_ru]

Используем AggreGate 5.31.04

[andyray06/rambler_ru]

В дополнение к возможным проблемам с NoSQL.

При удалении контекста устройства, в логах появляются следующие записи:

Код: Выделить всё

09.09.2016 11:59:27,532 ERROR org.apache.cassandra.db.filter.SliceQueryFilter Scanned over 100000 tombstones in aggregate.ag_change; query aborted (see tombstone_failure_threshold)     -     [ReadStage:27] org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns (SliceQueryFilter.java:206)
09.09.2016 11:59:27,534 ERROR org.apache.cassandra.service.CassandraDaemon Exception in thread Thread[ReadStage:27,5,main]     -     [ReadStage:27] org.apache.cassandra.service.CassandraDaemon$2.uncaughtException (CassandraDaemon.java:199)
java.lang.RuntimeException: org.apache.cassandra.db.filter.TombstoneOverwhelmingException
   at org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:2008)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.cassandra.db.filter.TombstoneOverwhelmingException
   at org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(SliceQueryFilter.java:208)
   at org.apache.cassandra.db.filter.QueryFilter.collateColumns(QueryFilter.java:122)
   at org.apache.cassandra.db.filter.QueryFilter.collateOnDiskAtom(QueryFilter.java:80)
   at org.apache.cassandra.db.RowIteratorFactory$2.getReduced(RowIteratorFactory.java:101)
   at org.apache.cassandra.db.RowIteratorFactory$2.getReduced(RowIteratorFactory.java:75)
   at org.apache.cassandra.utils.MergeIterator$ManyToOne.consume(MergeIterator.java:115)
   at org.apache.cassandra.utils.MergeIterator$ManyToOne.computeNext(MergeIterator.java:98)
   at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
   at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
   at org.apache.cassandra.db.ColumnFamilyStore$9.computeNext(ColumnFamilyStore.java:1597)
   at org.apache.cassandra.db.ColumnFamilyStore$9.computeNext(ColumnFamilyStore.java:1593)
   at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
   at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
   at org.apache.cassandra.db.ColumnFamilyStore.filter(ColumnFamilyStore.java:1756)
   at org.apache.cassandra.db.ColumnFamilyStore.getRangeSlice(ColumnFamilyStore.java:1714)
   at org.apache.cassandra.db.RangeSliceCommand.executeLocally(RangeSliceCommand.java:137)
   at org.apache.cassandra.service.StorageProxy$LocalRangeSliceRunnable.runMayThrow(StorageProxy.java:1461)
   at org.apache.cassandra.service.StorageProxy$DroppableRunnable.run(StorageProxy.java:2004)
   ... 3 more
09.09.2016 11:59:37,272 WARN  ag.context.events         Error removing persistent events from context 'opcua'     -     [Action / Удалить] com.tibbo.linkserver.context.BaseServerContext.destroy (BaseServerContext.java:770)
java.lang.RuntimeException: com.netflix.astyanax.connectionpool.exceptions.OperationTimeoutException: OperationTimeoutException: [host=10.0.250.219(10.0.250.219):9160, latency=10036(10036), attempts=1]TimedOutException()
   at com.netflix.astyanax.thrift.ThriftAllRowsQueryImpl.getNextBlock(ThriftAllRowsQueryImpl.java:105)
   at com.netflix.astyanax.thrift.ThriftAllRowsImpl$1.hasNext(ThriftAllRowsImpl.java:96)
   at com.tibbo.linkserver.plugin.persistence.nosql.cassandra.EmbeddedCassandraService.removeEvents(EmbeddedCassandraService.java:381)
   at com.tibbo.linkserver.plugin.persistence.nosql.NoSqlEventDao.deleteEvents(NoSqlEventDao.java:421)
   at com.tibbo.linkserver.plugin.persistence.nosql.NoSqlEventDao.deleteEvents(NoSqlEventDao.java:386)
   at com.tibbo.linkserver.context.BaseServerContext.destroy(BaseServerContext.java:766)
   at com.tibbo.linkserver.device.DefaultDeviceContext.destroy(DefaultDeviceContext.java:696)
   at com.tibbo.aggregate.common.context.AbstractContext.destroyChild(AbstractContext.java:1316)
   at com.tibbo.linkserver.context.EditableChildrenContext.destroyChild(EditableChildrenContext.java:492)
   at com.tibbo.linkserver.context.EditableChildrenContext.callFdelete(EditableChildrenContext.java:539)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   at java.lang.reflect.Method.invoke(Method.java:498)
   at com.tibbo.aggregate.common.context.AbstractContext.executeImplementationMethod(AbstractContext.java:3009)
   at com.tibbo.aggregate.common.context.AbstractContext.executeImplementation(AbstractContext.java:2949)
   at com.tibbo.aggregate.common.context.AbstractContext.callFunction(AbstractContext.java:2894)
   at com.tibbo.aggregate.common.context.AbstractContext.callFunction(AbstractContext.java:3042)
   at com.tibbo.aggregate.common.context.AbstractContext.callFunction(AbstractContext.java:3048)
   at com.tibbo.linkserver.action.CallFunctionAction$CallFunctionActionImpl.execute(CallFunctionAction.java:292)
   at com.tibbo.linkserver.action.CallFunctionAction$CallFunctionActionImpl.execute(CallFunctionAction.java:236)
   at com.tibbo.aggregate.common.action.SingleThreadAction$ActionThread.run(SingleThreadAction.java:261)
Caused by: com.netflix.astyanax.connectionpool.exceptions.OperationTimeoutException: OperationTimeoutException: [host=10.0.250.219(10.0.250.219):9160, latency=10036(10036), attempts=1]TimedOutException()
   at com.netflix.astyanax.thrift.ThriftConverter.ToConnectionPoolException(ThriftConverter.java:171)
   at com.netflix.astyanax.thrift.AbstractOperationImpl.execute(AbstractOperationImpl.java:65)
   at com.netflix.astyanax.thrift.AbstractOperationImpl.execute(AbstractOperationImpl.java:28)
   at com.netflix.astyanax.thrift.ThriftSyncConnectionFactoryImpl$ThriftConnection.execute(ThriftSyncConnectionFactoryImpl.java:153)
   at com.netflix.astyanax.connectionpool.impl.AbstractExecuteWithFailoverImpl.tryOperation(AbstractExecuteWithFailoverImpl.java:119)
   at com.netflix.astyanax.connectionpool.impl.AbstractHostPartitionConnectionPool.executeWithFailover(AbstractHostPartitionConnectionPool.java:352)
   at com.netflix.astyanax.thrift.ThriftAllRowsQueryImpl.getNextBlock(ThriftAllRowsQueryImpl.java:73)
   ... 21 more
Caused by: TimedOutException()
   at org.apache.cassandra.thrift.Cassandra$get_range_slices_result$get_range_slices_resultStandardScheme.read(Cassandra.java:17448)
   at org.apache.cassandra.thrift.Cassandra$get_range_slices_result$get_range_slices_resultStandardScheme.read(Cassandra.java:17397)
   at org.apache.cassandra.thrift.Cassandra$get_range_slices_result.read(Cassandra.java:17323)
   at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:78)
   at org.apache.cassandra.thrift.Cassandra$Client.recv_get_range_slices(Cassandra.java:802)
   at org.apache.cassandra.thrift.Cassandra$Client.get_range_slices(Cassandra.java:786)
   at com.netflix.astyanax.thrift.ThriftAllRowsQueryImpl$1.internalExecute(ThriftAllRowsQueryImpl.java:81)
   at com.netflix.astyanax.thrift.ThriftAllRowsQueryImpl$1.internalExecute(ThriftAllRowsQueryImpl.java:76)
   at com.netflix.astyanax.thrift.AbstractOperationImpl.execute(AbstractOperationImpl.java:60)
   ... 26 more

[anton_logoyskiy/tibbo_com]

Андрей, добрый день!

Я сегодня пришлю Вам ссылки на исправленную версию.

С уважением,
Антон Логойский
Tibbo Systems

[andyray06/rambler_ru]

Антон, здравствуйте!

Есть какие-нибудь новости по исправлениям? Ссылки не видел ни в PM, ни на почте.
Пробовали перевести хранилище событий на MySQL, проблема с недоступностью истории событий разрешилась, но с производительностью все так же.

В целом, отмечаются проблемы следующего плана:

Спустя некоторое время после перезагрузки сервера заканчивается HEAP, что вызывает постоянное срабатывание gc со всеми вытекающими. Под HEAP на данный момент выделено 20 Гб.
vmoptions следующие, если интересно:


Код: Выделить всё

-server
-Xms20480m
-Xmx20480m
-Xss512k
-XX:MaxPermSize=256m
-XX:+UseConcMarkSweepGC
-XX:+CMSClassUnloadingEnabled
-XX:-OmitStackTraceInFastThrow
-Duser.language=ru
-Dswing.systemlaf=javax.swing.plaf.nimbus.NimbusLookAndFeel

-XX:+UseCMSInitiatingOccupancyOnly
-XX:CMSInitiatingOccupancyFraction=70
-XX:+ScavengeBeforeFullGC
-XX:+CMSScavengeBeforeRemark
-XX:+CMSParallelRemarkEnabled
-XX:+UseParNewGC
-XX:NewRatio=3
-XX:SurvivorRatio=4

В ином случае все как описано в первом посте, загрузка памяти где-то на уровне 60% и постоянный рост показателя длины очереди событий.

Своими силами довольно сложно как-то подробнее диагностировать в чем проблема, то-ли дело в конфигурации "проекта", то-ли в настройках JVM, СУБД и т.д. Буду признателен, если подскажете способ для более точной диагностики.

[andyray06/rambler_ru]

Обновили версию сервера AG до 5.31.05, проблема с бесконечным ростом очереди событий осталась. Проявляется спустя несколько часов (около 12-16 если быть точнее) после перезагрузки сервера.