============================== SObjectizer_ v.4.4 beta3 Notes ============================== :Author: Евгений Охотников :Contact: eao197 at intervale dot ru; eao197 at yahoo dot com :Date: 2006.11.02 .. _SObjectizer: http://sobjectizer.sourceforge.net .. contents:: Введение ======== Это небольшой рассказ об основных изменениях в SObjectizer v.4.4.b3 по сравнению с предыдущими бета-версиями. О том, как это было и что из этого получилось. А так же несколько слов о направлениях дальнейшего развития SObjectizer (может быть излишне оптимистичных, но все-таки). Главной целью версии v.4.4.b3 была оптимизация работы SObjectizer и повышение его скорости. Поскольку исторически сложилось так, что серьезных оптимизаций SObjectizer никогда на выполнялось -- он работал, работал стабильно и достаточно быстро. Вначале SObjectizer наполнялся функциональностью. Затем был период небольшого застоя в его развитии, связанный с необходимостью определения будущего этого проекта. И только с началом перевода SObjectizer и сопутствующих ему фреймворков в категорию OpenSource проектов появилась необходимость (как следствие и возможности) серьезной оптимизации. Первым шагом в данном направлении стала версия v.4.4.b3. Повышение производительности ============================ В версии v.4.4.b3 удалось уделить внимание одной, но очень важной составляющей производительности SObjectizer: скорости отсылки сообщений и диспетчеризации событий. Для этого в состав тестов SObjectizer было добавлено несколько benchmark-ов, которые использовались при профилировании. Поэтому можно сказать, что производительности SObjectizer была повышена на основании показаний этих тестов. Описываемые ниже тесты дают синтетическую оценку производительности SObjectizer. Скорее всего реальные приложения на SObjectizer будут показывать несколько иные результаты, поскольку там на производительность окажет влияние значительно большее количество факторов чем в данных тестах. Однако, эти benchmark-и позволяют составить впечатление о скорости работы и накладных расходах самого SObjectizer. Тесты-benchmark-и ----------------- Ниже коротко описываются использованные при профилировании SObjectizer тесты и приводятся результаты запуска тестов и усредненные результаты замеряемых параметров. Замеры выполнялись на моем ноутбуке с процессором Intel Pentium-M 1.5GHz, оперативной памятью 512Mb под управлением Windows XP SP2. Примеры компилировались компилятором Visual C++ 7.1 (опция ``-O2``). Где возможно, приводятся показания такого же benchmark-а для v.4.4.b2. Все описанные ниже тесты входят в дистрибутив SObjectizer v.4.4.b3, они располагаются в каталоге ``test/bench`` и компилируются автоматически при выдаче команды: :: ruby test/build_tests.rb --mxx-cpp-release Тест send_msg ~~~~~~~~~~~~~ В этом тесте есть один агент, который после своего старта отсылает N собственных сообщений. Эти сообщения никто не обрабатывает, поэтому данный тест показывает скорость работы самой функции ``send_msg``. Средний показатель: 390376 сообщения в секунду. *Лучший показатель для v.4.4.b2: 236967 сообщений в секунду.* Тест send_and_process_msg ~~~~~~~~~~~~~~~~~~~~~~~~~ В этом тесте есть один агент, который после своего старта отсылает N собственных сообщений, после чего обрабатывает их все сам. Этот тест показывает скорость работы ``send_msg`` в условиях, когда генерируются заявки диспетчеру на обработку событий, и скорость работы диспетчера по обработке имеющихся у него заявок. Средний показатель: отсылка 242569.8 сообщений в секунду и обработка 485592.8 заявок в секунду. *Лучший показатель для v.4.4.b2: отсылка 130714 сообщений в секунду и обработка 290698 заявок в секунду.* Тест insend_and_process_msg ~~~~~~~~~~~~~~~~~~~~~~~~~~~ Аналог `Тест send_and_process_msg`_, но осуществляется обработка insend-событий (т.е. событие обрабатывается то возврата из ``send_msg``). Средний показатель: отсылка и обработка 200239.4 сообщений в секунду. *Лучший показатель для v.4.4.b2: отсылка и обработка 114286 сообщений в секунду.* Тест process_state_changes ~~~~~~~~~~~~~~~~~~~~~~~~~~ В этом тесте есть агент, который имеет 10 состояний и десять событий (по одному событию для каждого состояния). Сначала агент отсылает N сообщений, после чего обрабатывает их все сам. Но при обработке очередного сообщения он переводит самого себя из одного состояния в другое (из первого во второе, из второго в третье, ..., из десятого обратно в первое). Этот тест показывает скорость работы ``send_msg`` для случая, когда сообщение является инцидентом нескольких событий, и скорость работы диспетчера по обработке заявок для которых нужно выбирать событие в зависимости от текущего состояния агента. Средний показатель: отсылка 50743.34 сообщений в секунду и обработка 76582.98 заявок в секунду. *Лучший показатель для v.4.4.b2: отсылка 47755 сообщений в секунду и обработка 66667 заявок в секунду.* Тест send_agents_msg_self ~~~~~~~~~~~~~~~~~~~~~~~~~ В этом тесте регистрируются N агентов, M из которых отсылают сообщения случайно выбранному агенту. Замеряется время отсылки этих M сообщений. Данный тест выявляет влияние количества зарегистрированных агентов на время работы ``send_msg``. Средние показатели (для N=10000, 20000 и 100000 агентов; M=5000, 10000, 20000 сообщений): +------+--------+----------+--------+ | | 5000| 10000| 20000| +------+--------+----------+--------+ | 10000|160282.0| | | +------+--------+----------+--------+ | 20000|107308.2| 128205.0| | +------+--------+----------+--------+ |100000|118289.6| 109317.84|114299.8| +------+--------+----------+--------+ *Лучшие показатели для v.4.4.b2:* +------+--------+----------+--------+ | | 5000| 10000| 20000| +------+--------+----------+--------+ | 10000|108696.0| | | +------+--------+----------+--------+ | 20000| 80645.5| 90901.1| | +------+--------+----------+--------+ |100000| 79365.1| 80000.0| 80000.0| +------+--------+----------+--------+ Тест customer_ring ~~~~~~~~~~~~~~~~~~ Этот тест был взят из описания реализации механизма actor-ов в языке Scala [#ScalaActors]_. В нем организуется кольцо из N агентов, по которому движутся M токенов. Когда агент получает от своего соседа слева токен, он передает токен соседу справа. Работа теста завершается когда все M токенов сделают полный оборот по кольцу (т.е. в процессе теста происходит отсылка N*M сообщение о обработка N*M событий у N агентов). Тест был выполнен для трех основых диспетчеров: с одной рабочей нитью (с пасивными агентами), с активными агентами и с активными группами. Средние показатели для диспетчера с одной рабочей нитью (для N=1000, 2000, 5000, 10000, 20000, 50000, 100000; M=100), в третьем столбце курсивом показаны лучшие значения для v.4.4.b2: +-------+--------+----------+ | | beta3| beta2| +-------+--------+----------+ | 1000|165796.9| *98425.1*| +-------+--------+----------+ | 2000|163670.7| *96246.3*| +-------+--------+----------+ | 5000|154145.2| *92489.8*| +-------+--------+----------+ | 10000|148359.3| *90391.3*| +-------+--------+----------+ | 20000|140784.1| *87973.9*| +-------+--------+----------+ | 50000|132692.9| *84632.4*| +-------+--------+----------+ | 100000|128876.3| *83333.3*| +-------+--------+----------+ Средние показатели для диспетчера с активными агентами (для N=100, 200, 500, 1000; M=50), в третьем столбце курсивом показаны лучшие значения для v.4.4.b2: +----+--------+---------+ | | beta3 | beta2| +----+--------+---------+ | 100|148292.7|*80645.1*| +----+--------+---------+ | 200|125581.2|*80000.0*| +----+--------+---------+ | 500|131177.2|*72886.2*| +----+--------+---------+ |1000|125204.9|*68119.8*| +----+--------+---------+ Средние показатели для диспетчера с активными группами (для N=1000, 2000, 5000, 10000, 20000, 50000, 100000; M=100; 100 активных групп), в третьем столбце курсивом показаны лучшие значения для v.4.4.b2: +------+--------+----------+ | |beta3 |beta2 | +------+--------+----------+ | 1000|137365.5| *91407.6*| +------+--------+----------+ | 2000|142840.8| *88261.2*| +------+--------+----------+ | 5000|135150.2| *82263.9*| +------+--------+----------+ | 10000|123553.7| *82365.5*| +------+--------+----------+ | 20000|108772.4| *74288.6*| +------+--------+----------+ | 50000| 99505.5| *70082.9*| +------+--------+----------+ |100000| 95187.4| *66521.2*| +------+--------+----------+ .. [#ScalaActors] *Philipp Haller, Martin Odersky* Event-Based Programming without Inversion of Control, http://scala.epfl.ch Проведенные модификации ----------------------- Ниже коротко описываются основные оптимизации, которые были сделаны в SObjectizer v.4.4.b3. К сожалению, при проведении данных работ не осталось заметок о том, какой вклад в повышение производительности сделала та или иная оптимизация. Какие-то оптимизации были более выгодными и давали прирост в 5-7%, какие-то не столь заметными, но в результате прирост скорости работы SObjectizer оказался довольно серьезным. Используется класс std::priority_queue вместо std::multimap ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Диспетчер размещает все поступившие ему заявки в приоритетную очередь. Первоначально данная очередь была реализована с помощью ``std::multimap``. Но замеры показали, что ``std::priority_queue`` работает эффективнее. Специальная модификация класса so_4::rt::comm_channel_t ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ В предыдущих версиях класс ``so_4::rt::comm_channel_t`` хранил два объекта ``std::string``. Всегда, даже в случаях, когда никаких значений для ``comm_channel_t`` не задавалось: :: class SO_4_TYPE comm_channel_t { ... private : //! Имя агента-коммуникатора. std::string m_comm_agent; //! Имя клиента в коммуникаторе. std::string m_client; }; Оказалось, что даже пустые объекты ``std::string`` в ``comm_channel_t`` очень дороги. А ведь это очень распространенный случай -- большинство сообщений/событий в SObjectizer-приложении возникают и обрабатываются локально. Но объект ``comm_channel_t`` все равно создается для каждого сообщения/события. Поэтому в v.4.4.b3 используется специальная версия ``comm_channel_t``, оптимизированная для случая пустых значений: :: class SO_4_TYPE comm_channel_t { public : /*! * \since v.4.4.b3 * \brief Специальный тип, объекты которого будут использоваться * для указания того, что comm_channel_t относится к localhost. */ struct localhost_mark_t {}; ... private : //! Имя агента-коммуникатора. /*! Сохраняем значение только, если оно задано. */ std::auto_ptr< std::string > m_comm_agent; //! Имя клиента в коммуникаторе. /*! Сохраняем значение только, если оно задано. */ std::auto_ptr< std::string > m_client; /*! * \since v.4.4.b3 * \brief Признак того, что канал является localhost. */ bool m_is_localhost; }; Удален контроль за контекстом нити в методе so_change_state ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Метод ``so_change_state`` был добавлен в SObjectizer специально для того, чтобы только агенты в обработчиках своих событий могли изменять собственное состояние. При этом в SObjectizer был введен дополнительный контроль на уровне диспетчера: для агента сохранялась метка нити, на которой диспетчер запускал событие агента. И если в ``so_change_state`` оказывалось, что текущая нить не совпадает в отмеченной диспетчером, то ``so_change_state`` отказывался менять состояние агента. За все время существования ``so_change_state`` не было выявлено ни одного случая такого нарушения. Вместе с тем, реализация подобного контроля была дорогостоящей, т.к. требовался дополнительный объект-mutex. В результате от контроля контекста нити в ``so_change_state`` было решено отказаться, что позволило обойтись без работы с mutex-ом при диспетчеризации событий агентов. Класс so_4::rt::impl::std_delivery_man_t оптимизирован для случая одного события ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Эта оптимизация похожа на модификацию ``so_4::rt::comm_channel_t`` -- поскольку класс ``std_delivery_man_t`` в подавляющем большинстве случаев работал только с одной заявкой, то он был модифицирован так, чтобы создавать дополнительные ресурсы только тогда, когда это нужно. В предшествующих версиях ``std_delivery_man_t`` имел вид: :: class std_delivery_man_t : public delivery_man_t { public : ... private : class group_key_t { ... }; class group_t { ... private : event_data_single_ptr_list_t m_events; }; typedef std::map< group_key_t, group_t, std::less< group_key_t > > group_map_t; group_map_t m_groups; }; т.е. экземпляр ``std::map`` создавался всегда и внутри этого экземпляра распределялась память хотя бы для одной пары ````. Аналогично и со списком ``std_delivery_man_t::group_t::m_events``. В новой версии ``std_delivery_man_t`` имеет вид: :: class std_delivery_man_t : public delivery_man_t { public : ... class group_key_t { ... }; class group_t { ... private : //! Для случая, когда в группу входит только одно событие. event_data_single_t * m_single_event; //! Для случая, когда в группу входит больше одного события. std::auto_ptr< event_data_single_ptr_list_t > m_events; }; typedef std::map< group_key_t, group_t, std::less< group_key_t > > group_map_t; private : //! \name Для случая, когда диспетчируется всего одно событие. //! \{ //! Приоритет диспетчируемого события. int m_single_event_priority; //! event_data для события. /*! * Если m_groups содержит 0, то m_single_event_data == 0 * означает, что ничего еще не диспетчировалось. */ event_data_single_t * m_single_event_data; //! \} //! Для случая, когда диспетчируется группа событий. std::auto_ptr< group_map_t > m_groups; }; Теперь, если ``std_delivery_man_t`` хранит только одно событие, то используется его атрибут ``std_delivery_man_t::m_single_event_data``. Аналогично и со списком ``std_delivery_man_t::group_t::m_events`` -- в случае единственного события в группе используется атрибут ``group_t::m_single_event``. В одном случае объект std_delivery_man_t создается на стеке ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ При генерации заявок диспетчеру во внутренностях ``send_msg`` в одном из мест объект ``std_delivery_man_t`` создается на стеке вместо размещения в динамической памяти через new. Это позволило отказаться от довольно дорогого обращения к new (и, следовательно, к еще одному объекту синхронизации где-то в дебрях стандартной библиотеки). Впечатления от игр с производительностью ---------------------------------------- Пожалуй, самый главный субъективный вывод -- это весьма трудоемкое и длительное занятие. Возможно, даже одно из самых сложных. И, как мне показалось, оно не столь увлекательное, как поиск ошибок (при поиске есть азарт, поскольку ошибка должна быть удалена, без этого нельзя, а вот оптимизация больше напоминает поиск черной кошки в темной комнате). Но это субъективные впечатления, объективные описаны ниже. new/delete -- это дорого, но пока не они являются узким местом ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ В процессе оптимизации предпринималось несколько попыток заменить для части классов стандартные new/delete специализированными версиям, заточенными специально под определенные сценарии использования этих классов. Но эффекта это не приносило, поскольку сейчас бутылочным горлышком является синхронизация. В первую очередь нужно избавляться от синхронизации ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ В некоторых самых критичных операциях (например, ``send_msg``, подсчет ссылок на сообщения, события, агентов) SObjectizer вынужден использовать примитивы синхронизации (разные типы mutex-ов). На данный момент это является самым большим препятствием на пути повышения произволительности SObjectizer. Первый пример. В ``send_msg`` ядро SObjectizer должно быть заблокировано для того, чтобы проверить наличие сообщения и создать внутренний описатель сообщения. Затем ядро SObjectizer должно быть разблокированно, чтобы можно было проверить корректность экземпляра сообщения. А потом вновь заблокированно, чтобы сгенерировать заявки на обработку порожденных сообщением событий. Если от одной из этих блокировок избавиться, то производительность операции ``send_msg`` сразу существенно повышается (на десятки тысяч сообщений в секунду на тесте customer_ring). Но избавиться пока не представляется возможным. Второй пример. Подсчет ссылок на экземпляры сообщений/событий. Для операций инкремента/декремента приходится блокировать поток на специальном синхронизирующем объекте. Применить т.н. *atomic* операции не представляется возможным, т.е. в рамках одной транзакции должно быть изменено сразу несколько ссылок. Например, для увеличения ссылки на событие нужно увеличить количество ссылок на событие, на сообщение-инцидент и на агента, который владеет сообщением-инцидентом. Atomic-операция может быть выполнена только над одним счетчиком ссылок, а остальные остаются незащищенными. Может быть, подсчет ссылок получится заменить *lock-free* списками для событий/сообщений/агентов и это позволит избавится от синхронизации. Но это уже направление для дальнейших работ. Самая выгодная оптимизация -- алгоритмическая, но, блин, не говорите мне... ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Все описанные выше оптимизации можно считать микрооптимизациями. Они не могут дать прироста производительности на порядки. Что и подтвержается полученными результатами тестов. Существует обоснованное мнение, что самые выгодные оптимизации -- алгоритмические, когда прирост производительности достигается сменой алгоритма. Я разделяю это мнение. Но... Весь фокус в том, что лучший и более производительный алгоритм еще нужно придумать или разыскать где-то в литературе. Так просто они на дороге не валяются. Вот ведь засада. Узкие места влияют друг на друга ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ В профайлере иногда можно увидеть, что какой-то метод работает слишком долго. Этот метод оптимизируется, профайлер показывает, что он стал работать быстрее, но общая производительность не изменилась. В чем дело? А дело в том, что другой метод блокирует влияние модификации. Например, оптимизация ``std_delivery_man_t`` не приводила к существенному изменению показателей тестов. Потому что сохранение контекста нити для ``so_change_state`` не дает этой оптимизации проявится. Поэтому иногда приходилось от каких-то оптимизаций поначалу отказываться (чтобы сохранить простоту исходного кода), а затем возвращаться к ним вновь. Направления дальнейшего развития ================================ Часть операций не подвергалась оптимизации вообще. Например, процедуры регистрации и дерегистрации агентов. А, как показывают замеры скорости регистрации в тесте customer_ring, ее скорость значительно уступает скорости ``send_msg`` или диспетчеризации события. В некоторых случаях, скажем, если в прикладной задаче часто создаются/уничтожаются агенты, это может стать проблемой. Но самым важным выводом из работ по созданию версии v.4.4.b3 стало то, что алгоритм работы транспортных агентов в SObjectizer неудовлетворителен. Он очень неэффективен, если обмент SOP-пакетами идет со скоростью нескольких десятков в секунду и с равномерным темпом (например, 75-100 миллисекунд). Корни этой проблемы растут из самых первых версий SObjectizer-4. Сейчас, после перехода на ACE для работы с коммуникационными средствами (сокетами, пайпами и др.), появляется возможность реализовать более эффективное поведение транспортных агентов за счет использования механизма ACE_Reactor. Именно этим проблемам будет уделяться основное внимание в следующей, четвертой, бета версии SObjectizer. Результаты тестовых прогонов benchmark-ов ========================================= :: *** *** test.bench.insend_and_process_msg *** Number of messages: 100000 Working: 0.515 sec Performance: 194175 msgs/sec Number of messages: 100000 Working: 0.516 sec Performance: 193798 msgs/sec Number of messages: 100000 Working: 0.484 sec Performance: 206612 msgs/sec Number of messages: 100000 Working: 0.5 sec Performance: 200000 msgs/sec Number of messages: 100000 Working: 0.484 sec Performance: 206612 msgs/sec *** *** test.bench.process_state_changes *** Number of messages (state changes): 100000 Sending messages: 1.969 sec Sending messages performance: 50787.2 msgs/sec Processing messages: 1.328 sec Processing messages performance: 75301.2 msgs/sec (state_changes/sec) Number of messages (state changes): 100000 Sending messages: 2.063 sec Sending messages performance: 48473.1 msgs/sec Processing messages: 1.343 sec Processing messages performance: 74460.2 msgs/sec (state_changes/sec) Number of messages (state changes): 100000 Sending messages: 1.953 sec Sending messages performance: 51203.3 msgs/sec Processing messages: 1.282 sec Processing messages performance: 78003.1 msgs/sec (state_changes/sec) Number of messages (state changes): 100000 Sending messages: 1.906 sec Sending messages performance: 52465.9 msgs/sec Processing messages: 1.313 sec Processing messages performance: 76161.5 msgs/sec (state_changes/sec) Number of messages (state changes): 100000 Sending messages: 1.969 sec Sending messages performance: 50787.2 msgs/sec Processing messages: 1.266 sec Processing messages performance: 78988.9 msgs/sec (state_changes/sec) *** *** test.bench.send_and_process_msg *** Number of messages: 100000 Sending messages: 0.422 sec Sending messages performance: 236967 msgs/sec Processing messages: 0.188 sec Processing messages performance: 531915 msgs/sec Number of messages: 100000 Sending messages: 0.406 sec Sending messages performance: 246305 msgs/sec Processing messages: 0.219 sec Processing messages performance: 456621 msgs/sec Number of messages: 100000 Sending messages: 0.406 sec Sending messages performance: 246305 msgs/sec Processing messages: 0.204 sec Processing messages performance: 490196 msgs/sec Number of messages: 100000 Sending messages: 0.422 sec Sending messages performance: 236967 msgs/sec Processing messages: 0.203 sec Processing messages performance: 492611 msgs/sec Number of messages: 100000 Sending messages: 0.406 sec Sending messages performance: 246305 msgs/sec Processing messages: 0.219 sec Processing messages performance: 456621 msgs/sec *** *** test.bench.send_msg *** Number of messages: 100000 Working: 0.25 sec Performance: 400000 msgs/sec Number of messages: 100000 Working: 0.266 sec Performance: 375940 msgs/sec Number of messages: 100000 Working: 0.266 sec Performance: 375940 msgs/sec Number of messages: 100000 Working: 0.25 sec Performance: 400000 msgs/sec Number of messages: 100000 Working: 0.25 sec Performance: 400000 msgs/sec *** *** test.bench.send_agents_msg_self 10000 5000 *** total: 0.031 sec, single send: 6.2e-006 sec, throughput: 161290 msgs/sec total: 0.032 sec, single send: 6.4e-006 sec, throughput: 156250 msgs/sec total: 0.031 sec, single send: 6.2e-006 sec, throughput: 161290 msgs/sec total: 0.031 sec, single send: 6.2e-006 sec, throughput: 161290 msgs/sec total: 0.031 sec, single send: 6.2e-006 sec, throughput: 161290 msgs/sec *** *** test.bench.send_agents_msg_self 20000 5000 *** total: 0.047 sec, single send: 9.4e-006 sec, throughput: 106383 msgs/sec total: 0.046 sec, single send: 9.2e-006 sec, throughput: 108696 msgs/sec total: 0.046 sec, single send: 9.2e-006 sec, throughput: 108696 msgs/sec total: 0.047 sec, single send: 9.4e-006 sec, throughput: 106383 msgs/sec total: 0.047 sec, single send: 9.4e-006 sec, throughput: 106383 msgs/sec *** *** test.bench.send_agents_msg_self 20000 10000 *** total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec *** *** test.bench.send_agents_msg_self 100000 5000 *** total: 0.031 sec, single send: 6.2e-006 sec, throughput: 161290 msgs/sec total: 0.046 sec, single send: 9.2e-006 sec, throughput: 108696 msgs/sec total: 0.046 sec, single send: 9.2e-006 sec, throughput: 108696 msgs/sec total: 0.047 sec, single send: 9.4e-006 sec, throughput: 106383 msgs/sec total: 0.047 sec, single send: 9.4e-006 sec, throughput: 106383 msgs/sec *** *** test.bench.send_agents_msg_self 100000 10000 *** total: 0.093 sec, single send: 9.3e-006 sec, throughput: 107527 msgs/sec total: 0.109 sec, single send: 1.09e-005 sec, throughput: 91743.1 msgs/sec total: 0.11 sec, single send: 1.1e-005 sec, throughput: 90909.1 msgs/sec total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec total: 0.078 sec, single send: 7.8e-006 sec, throughput: 128205 msgs/sec *** *** test.bench.send_agents_msg_self 100000 20000 *** total: 0.172 sec, single send: 8.6e-006 sec, throughput: 116279 msgs/sec total: 0.188 sec, single send: 9.4e-006 sec, throughput: 106383 msgs/sec total: 0.172 sec, single send: 8.6e-006 sec, throughput: 116279 msgs/sec total: 0.172 sec, single send: 8.6e-006 sec, throughput: 116279 msgs/sec total: 0.172 sec, single send: 8.6e-006 sec, throughput: 116279 msgs/sec *** *** test.bench.customer_ring -N 1000 -M 100 *** ring size: 1000; token count: 100; dispatcher: one thread registration=> total: 0.031000 sec, price: 0.000031 sec; troughput: 32258.064516 ringing=> total: 0.625000 sec, price: 0.000006 sec; troughput: 160000.000000 ring size: 1000; token count: 100; dispatcher: one thread registration=> total: 0.031000 sec, price: 0.000031 sec; troughput: 32258.064516 ringing=> total: 0.594000 sec, price: 0.000006 sec; troughput: 168350.168350 ring size: 1000; token count: 100; dispatcher: one thread registration=> total: 0.031000 sec, price: 0.000031 sec; troughput: 32258.064516 ringing=> total: 0.610000 sec, price: 0.000006 sec; troughput: 163934.426230 ring size: 1000; token count: 100; dispatcher: one thread registration=> total: 0.047000 sec, price: 0.000047 sec; troughput: 21276.595745 ringing=> total: 0.594000 sec, price: 0.000006 sec; troughput: 168350.168350 ring size: 1000; token count: 100; dispatcher: one thread registration=> total: 0.031000 sec, price: 0.000031 sec; troughput: 32258.064516 ringing=> total: 0.594000 sec, price: 0.000006 sec; troughput: 168350.168350 *** *** test.bench.customer_ring -N 2000 -M 100 *** ring size: 2000; token count: 100; dispatcher: one thread registration=> total: 0.079000 sec, price: 0.000039 sec; troughput: 25316.455696 ringing=> total: 1.218000 sec, price: 0.000006 sec; troughput: 164203.612479 ring size: 2000; token count: 100; dispatcher: one thread registration=> total: 0.078000 sec, price: 0.000039 sec; troughput: 25641.025641 ringing=> total: 1.219000 sec, price: 0.000006 sec; troughput: 164068.908942 ring size: 2000; token count: 100; dispatcher: one thread registration=> total: 0.078000 sec, price: 0.000039 sec; troughput: 25641.025641 ringing=> total: 1.219000 sec, price: 0.000006 sec; troughput: 164068.908942 ring size: 2000; token count: 100; dispatcher: one thread registration=> total: 0.078000 sec, price: 0.000039 sec; troughput: 25641.025641 ringing=> total: 1.219000 sec, price: 0.000006 sec; troughput: 164068.908942 ring size: 2000; token count: 100; dispatcher: one thread registration=> total: 0.078000 sec, price: 0.000039 sec; troughput: 25641.025641 ringing=> total: 1.235000 sec, price: 0.000006 sec; troughput: 161943.319838 *** *** test.bench.customer_ring -N 5000 -M 100 *** ring size: 5000; token count: 100; dispatcher: one thread registration=> total: 0.203000 sec, price: 0.000041 sec; troughput: 24630.541872 ringing=> total: 3.235000 sec, price: 0.000006 sec; troughput: 154559.505410 ring size: 5000; token count: 100; dispatcher: one thread registration=> total: 0.219000 sec, price: 0.000044 sec; troughput: 22831.050228 ringing=> total: 3.281000 sec, price: 0.000007 sec; troughput: 152392.563243 ring size: 5000; token count: 100; dispatcher: one thread registration=> total: 0.203000 sec, price: 0.000041 sec; troughput: 24630.541872 ringing=> total: 3.234000 sec, price: 0.000006 sec; troughput: 154607.297464 ring size: 5000; token count: 100; dispatcher: one thread registration=> total: 0.218000 sec, price: 0.000044 sec; troughput: 22935.779817 ringing=> total: 3.235000 sec, price: 0.000006 sec; troughput: 154559.505410 ring size: 5000; token count: 100; dispatcher: one thread registration=> total: 0.219000 sec, price: 0.000044 sec; troughput: 22831.050228 ringing=> total: 3.234000 sec, price: 0.000006 sec; troughput: 154607.297464 *** *** test.bench.customer_ring -N 10000 -M 100 *** ring size: 10000; token count: 100; dispatcher: one thread registration=> total: 0.437000 sec, price: 0.000044 sec; troughput: 22883.295195 ringing=> total: 6.750000 sec, price: 0.000007 sec; troughput: 148148.148148 ring size: 10000; token count: 100; dispatcher: one thread registration=> total: 0.453000 sec, price: 0.000045 sec; troughput: 22075.055188 ringing=> total: 6.734000 sec, price: 0.000007 sec; troughput: 148500.148500 ring size: 10000; token count: 100; dispatcher: one thread registration=> total: 0.438000 sec, price: 0.000044 sec; troughput: 22831.050228 ringing=> total: 6.750000 sec, price: 0.000007 sec; troughput: 148148.148148 ring size: 10000; token count: 100; dispatcher: one thread registration=> total: 0.438000 sec, price: 0.000044 sec; troughput: 22831.050228 ringing=> total: 6.734000 sec, price: 0.000007 sec; troughput: 148500.148500 ring size: 10000; token count: 100; dispatcher: one thread registration=> total: 0.453000 sec, price: 0.000045 sec; troughput: 22075.055188 ringing=> total: 6.734000 sec, price: 0.000007 sec; troughput: 148500.148500 *** *** test.bench.customer_ring -N 20000 -M 100 *** ring size: 20000; token count: 100; dispatcher: one thread registration=> total: 1.000000 sec, price: 0.000050 sec; troughput: 20000.000000 ringing=> total: 14.250000 sec, price: 0.000007 sec; troughput: 140350.877193 ring size: 20000; token count: 100; dispatcher: one thread registration=> total: 0.984000 sec, price: 0.000049 sec; troughput: 20325.203252 ringing=> total: 14.219000 sec, price: 0.000007 sec; troughput: 140656.867572 ring size: 20000; token count: 100; dispatcher: one thread registration=> total: 0.984000 sec, price: 0.000049 sec; troughput: 20325.203252 ringing=> total: 14.203000 sec, price: 0.000007 sec; troughput: 140815.320707 ring size: 20000; token count: 100; dispatcher: one thread registration=> total: 1.000000 sec, price: 0.000050 sec; troughput: 20000.000000 ringing=> total: 14.187000 sec, price: 0.000007 sec; troughput: 140974.131247 ring size: 20000; token count: 100; dispatcher: one thread registration=> total: 1.015000 sec, price: 0.000051 sec; troughput: 19704.433498 ringing=> total: 14.172000 sec, price: 0.000007 sec; troughput: 141123.341801 *** *** test.bench.customer_ring -N 50000 -M 100 *** ring size: 50000; token count: 100; dispatcher: one thread registration=> total: 2.750000 sec, price: 0.000055 sec; troughput: 18181.818182 ringing=> total: 37.703000 sec, price: 0.000008 sec; troughput: 132615.441742 ring size: 50000; token count: 100; dispatcher: one thread registration=> total: 2.766000 sec, price: 0.000055 sec; troughput: 18076.644975 ringing=> total: 37.640000 sec, price: 0.000008 sec; troughput: 132837.407014 ring size: 50000; token count: 100; dispatcher: one thread registration=> total: 2.766000 sec, price: 0.000055 sec; troughput: 18076.644975 ringing=> total: 37.703000 sec, price: 0.000008 sec; troughput: 132615.441742 ring size: 50000; token count: 100; dispatcher: one thread registration=> total: 2.765000 sec, price: 0.000055 sec; troughput: 18083.182640 ringing=> total: 37.656000 sec, price: 0.000008 sec; troughput: 132780.964521 ring size: 50000; token count: 100; dispatcher: one thread registration=> total: 2.766000 sec, price: 0.000055 sec; troughput: 18076.644975 ringing=> total: 37.703000 sec, price: 0.000008 sec; troughput: 132615.441742 *** *** test.bench.customer_ring -N 100000 -M 100 *** ring size: 100000; token count: 100; dispatcher: one thread registration=> total: 5.828000 sec, price: 0.000058 sec; troughput: 17158.544955 ringing=> total: 77.516000 sec, price: 0.000008 sec; troughput: 129005.624645 ring size: 100000; token count: 100; dispatcher: one thread registration=> total: 5.766000 sec, price: 0.000058 sec; troughput: 17343.045439 ringing=> total: 77.625000 sec, price: 0.000008 sec; troughput: 128824.476651 ring size: 100000; token count: 100; dispatcher: one thread registration=> total: 5.781000 sec, price: 0.000058 sec; troughput: 17298.045321 ringing=> total: 77.656000 sec, price: 0.000008 sec; troughput: 128773.050376 ring size: 100000; token count: 100; dispatcher: one thread registration=> total: 5.797000 sec, price: 0.000058 sec; troughput: 17250.301880 ringing=> total: 77.640000 sec, price: 0.000008 sec; troughput: 128799.587841 ring size: 100000; token count: 100; dispatcher: one thread registration=> total: 5.750000 sec, price: 0.000058 sec; troughput: 17391.304348 ringing=> total: 77.532000 sec, price: 0.000008 sec; troughput: 128979.002218 *** *** test.bench.customer_ring -N 100 -M 50 -D AO *** ring size: 100; token count: 50; dispatcher: active objects registration=> total: 0.031000 sec, price: 0.000310 sec; troughput: 3225.806452 ringing=> total: 0.032000 sec, price: 0.000006 sec; troughput: 156250.000000 ring size: 100; token count: 50; dispatcher: active objects registration=> total: 0.031000 sec, price: 0.000310 sec; troughput: 3225.806452 ringing=> total: 0.031000 sec, price: 0.000006 sec; troughput: 161290.322581 ring size: 100; token count: 50; dispatcher: active objects registration=> total: 0.031000 sec, price: 0.000310 sec; troughput: 3225.806452 ringing=> total: 0.031000 sec, price: 0.000006 sec; troughput: 161290.322581 ring size: 100; token count: 50; dispatcher: active objects registration=> total: 0.016000 sec, price: 0.000160 sec; troughput: 6250.000000 ringing=> total: 0.047000 sec, price: 0.000009 sec; troughput: 106382.978723 ring size: 100; token count: 50; dispatcher: active objects registration=> total: 0.015000 sec, price: 0.000150 sec; troughput: 6666.666667 ringing=> total: 0.032000 sec, price: 0.000006 sec; troughput: 156250.000000 *** *** test.bench.customer_ring -N 200 -M 50 -D AO *** ring size: 200; token count: 50; dispatcher: active objects registration=> total: 0.047000 sec, price: 0.000235 sec; troughput: 4255.319149 ringing=> total: 0.094000 sec, price: 0.000009 sec; troughput: 106382.978723 ring size: 200; token count: 50; dispatcher: active objects registration=> total: 0.046000 sec, price: 0.000230 sec; troughput: 4347.826087 ringing=> total: 0.094000 sec, price: 0.000009 sec; troughput: 106382.978723 ring size: 200; token count: 50; dispatcher: active objects registration=> total: 0.047000 sec, price: 0.000235 sec; troughput: 4255.319149 ringing=> total: 0.078000 sec, price: 0.000008 sec; troughput: 128205.128205 ring size: 200; token count: 50; dispatcher: active objects registration=> total: 0.046000 sec, price: 0.000230 sec; troughput: 4347.826087 ringing=> total: 0.063000 sec, price: 0.000006 sec; troughput: 158730.158730 ring size: 200; token count: 50; dispatcher: active objects registration=> total: 0.047000 sec, price: 0.000235 sec; troughput: 4255.319149 ringing=> total: 0.078000 sec, price: 0.000008 sec; troughput: 128205.128205 *** *** test.bench.customer_ring -N 500 -M 50 -D AO *** ring size: 500; token count: 50; dispatcher: active objects registration=> total: 0.125000 sec, price: 0.000250 sec; troughput: 4000.000000 ringing=> total: 0.187000 sec, price: 0.000007 sec; troughput: 133689.839572 ring size: 500; token count: 50; dispatcher: active objects registration=> total: 0.125000 sec, price: 0.000250 sec; troughput: 4000.000000 ringing=> total: 0.188000 sec, price: 0.000008 sec; troughput: 132978.723404 ring size: 500; token count: 50; dispatcher: active objects registration=> total: 0.125000 sec, price: 0.000250 sec; troughput: 4000.000000 ringing=> total: 0.187000 sec, price: 0.000007 sec; troughput: 133689.839572 ring size: 500; token count: 50; dispatcher: active objects registration=> total: 0.125000 sec, price: 0.000250 sec; troughput: 4000.000000 ringing=> total: 0.204000 sec, price: 0.000008 sec; troughput: 122549.019608 ring size: 500; token count: 50; dispatcher: active objects registration=> total: 0.125000 sec, price: 0.000250 sec; troughput: 4000.000000 ringing=> total: 0.188000 sec, price: 0.000008 sec; troughput: 132978.723404 *** *** test.bench.customer_ring -N 1000 -M 50 -D AO *** ring size: 1000; token count: 50; dispatcher: active objects registration=> total: 0.296000 sec, price: 0.000296 sec; troughput: 3378.378378 ringing=> total: 0.407000 sec, price: 0.000008 sec; troughput: 122850.122850 ring size: 1000; token count: 50; dispatcher: active objects registration=> total: 0.313000 sec, price: 0.000313 sec; troughput: 3194.888179 ringing=> total: 0.390000 sec, price: 0.000008 sec; troughput: 128205.128205 ring size: 1000; token count: 50; dispatcher: active objects registration=> total: 0.281000 sec, price: 0.000281 sec; troughput: 3558.718861 ringing=> total: 0.422000 sec, price: 0.000008 sec; troughput: 118483.412322 ring size: 1000; token count: 50; dispatcher: active objects registration=> total: 0.281000 sec, price: 0.000281 sec; troughput: 3558.718861 ringing=> total: 0.406000 sec, price: 0.000008 sec; troughput: 123152.709360 ring size: 1000; token count: 50; dispatcher: active objects registration=> total: 0.328000 sec, price: 0.000328 sec; troughput: 3048.780488 ringing=> total: 0.375000 sec, price: 0.000008 sec; troughput: 133333.333333 *** *** test.bench.customer_ring -N 1000 -M 100 -D AG -G 100 *** ring size: 1000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.047000 sec, price: 0.000047 sec; troughput: 21276.595745 ringing=> total: 0.719000 sec, price: 0.000007 sec; troughput: 139082.058414 ring size: 1000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.047000 sec, price: 0.000047 sec; troughput: 21276.595745 ringing=> total: 0.718000 sec, price: 0.000007 sec; troughput: 139275.766017 ring size: 1000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.047000 sec, price: 0.000047 sec; troughput: 21276.595745 ringing=> total: 0.735000 sec, price: 0.000007 sec; troughput: 136054.421769 ring size: 1000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.047000 sec, price: 0.000047 sec; troughput: 21276.595745 ringing=> total: 0.750000 sec, price: 0.000008 sec; troughput: 133333.333333 ring size: 1000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.047000 sec, price: 0.000047 sec; troughput: 21276.595745 ringing=> total: 0.719000 sec, price: 0.000007 sec; troughput: 139082.058414 *** *** test.bench.customer_ring -N 2000 -M 100 -D AG -G 100 *** ring size: 2000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.187000 sec, price: 0.000093 sec; troughput: 10695.187166 ringing=> total: 1.391000 sec, price: 0.000007 sec; troughput: 143781.452193 ring size: 2000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.188000 sec, price: 0.000094 sec; troughput: 10638.297872 ringing=> total: 1.406000 sec, price: 0.000007 sec; troughput: 142247.510669 ring size: 2000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.187000 sec, price: 0.000093 sec; troughput: 10695.187166 ringing=> total: 1.407000 sec, price: 0.000007 sec; troughput: 142146.410803 ring size: 2000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.187000 sec, price: 0.000093 sec; troughput: 10695.187166 ringing=> total: 1.391000 sec, price: 0.000007 sec; troughput: 143781.452193 ring size: 2000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.187000 sec, price: 0.000093 sec; troughput: 10695.187166 ringing=> total: 1.406000 sec, price: 0.000007 sec; troughput: 142247.510669 *** *** test.bench.customer_ring -N 5000 -M 100 -D AG -G 100 *** ring size: 5000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.468000 sec, price: 0.000094 sec; troughput: 10683.760684 ringing=> total: 3.844000 sec, price: 0.000008 sec; troughput: 130072.840791 ring size: 5000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.703000 sec, price: 0.000141 sec; troughput: 7112.375533 ringing=> total: 3.563000 sec, price: 0.000007 sec; troughput: 140331.181589 ring size: 5000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.579000 sec, price: 0.000116 sec; troughput: 8635.578584 ringing=> total: 3.750000 sec, price: 0.000008 sec; troughput: 133333.333333 ring size: 5000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.469000 sec, price: 0.000094 sec; troughput: 10660.980810 ringing=> total: 3.797000 sec, price: 0.000008 sec; troughput: 131682.907559 ring size: 5000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.719000 sec, price: 0.000144 sec; troughput: 6954.102921 ringing=> total: 3.563000 sec, price: 0.000007 sec; troughput: 140331.181589 *** *** test.bench.customer_ring -N 10000 -M 100 -D AG -G 100 *** ring size: 10000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.937000 sec, price: 0.000094 sec; troughput: 10672.358591 ringing=> total: 8.094000 sec, price: 0.000008 sec; troughput: 123548.307388 ring size: 10000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.844000 sec, price: 0.000084 sec; troughput: 11848.341232 ringing=> total: 8.156000 sec, price: 0.000008 sec; troughput: 122609.122119 ring size: 10000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.937000 sec, price: 0.000094 sec; troughput: 10672.358591 ringing=> total: 8.094000 sec, price: 0.000008 sec; troughput: 123548.307388 ring size: 10000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.921000 sec, price: 0.000092 sec; troughput: 10857.763301 ringing=> total: 8.047000 sec, price: 0.000008 sec; troughput: 124269.914254 ring size: 10000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 0.922000 sec, price: 0.000092 sec; troughput: 10845.986985 ringing=> total: 8.078000 sec, price: 0.000008 sec; troughput: 123793.018074 *** *** test.bench.customer_ring -N 20000 -M 100 -D AG -G 100 *** ring size: 20000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 1.672000 sec, price: 0.000084 sec; troughput: 11961.722488 ringing=> total: 18.468000 sec, price: 0.000009 sec; troughput: 108295.429933 ring size: 20000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 1.782000 sec, price: 0.000089 sec; troughput: 11223.344557 ringing=> total: 18.359000 sec, price: 0.000009 sec; troughput: 108938.395337 ring size: 20000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 1.688000 sec, price: 0.000084 sec; troughput: 11848.341232 ringing=> total: 18.437000 sec, price: 0.000009 sec; troughput: 108477.518034 ring size: 20000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 1.859000 sec, price: 0.000093 sec; troughput: 10758.472297 ringing=> total: 18.297000 sec, price: 0.000009 sec; troughput: 109307.536755 ring size: 20000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 1.781000 sec, price: 0.000089 sec; troughput: 11229.646266 ringing=> total: 18.375000 sec, price: 0.000009 sec; troughput: 108843.537415 *** *** test.bench.customer_ring -N 50000 -M 100 -D AG -G 100 *** ring size: 50000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 4.515000 sec, price: 0.000090 sec; troughput: 11074.197121 ringing=> total: 50.172000 sec, price: 0.000010 sec; troughput: 99657.179303 ring size: 50000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 4.766000 sec, price: 0.000095 sec; troughput: 10490.977759 ringing=> total: 49.937000 sec, price: 0.000010 sec; troughput: 100126.158960 ring size: 50000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 4.094000 sec, price: 0.000082 sec; troughput: 12212.994626 ringing=> total: 50.735000 sec, price: 0.000010 sec; troughput: 98551.295950 ring size: 50000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 4.328000 sec, price: 0.000087 sec; troughput: 11552.680222 ringing=> total: 50.359000 sec, price: 0.000010 sec; troughput: 99287.118489 ring size: 50000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 4.625000 sec, price: 0.000092 sec; troughput: 10810.810811 ringing=> total: 50.047000 sec, price: 0.000010 sec; troughput: 99906.088277 *** *** test.bench.customer_ring -N 100000 -M 100 -D AG -G 100 *** ring size: 100000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 9.047000 sec, price: 0.000090 sec; troughput: 11053.387863 ringing=> total: 105.328000 sec, price: 0.000011 sec; troughput: 94941.516026 ring size: 100000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 9.360000 sec, price: 0.000094 sec; troughput: 10683.760684 ringing=> total: 104.953000 sec, price: 0.000010 sec; troughput: 95280.744714 ring size: 100000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 8.938000 sec, price: 0.000089 sec; troughput: 11188.185276 ringing=> total: 105.000000 sec, price: 0.000010 sec; troughput: 95238.095238 ring size: 100000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 9.203000 sec, price: 0.000092 sec; troughput: 10866.021949 ringing=> total: 105.188000 sec, price: 0.000011 sec; troughput: 95067.878465 ring size: 100000; token count: 100; dispatcher: active groups; group count: 100 registration=> total: 8.985000 sec, price: 0.000090 sec; troughput: 11129.660545 ringing=> total: 104.812000 sec, price: 0.000010 sec; troughput: 95408.922642 .. vim:ts=2:sts=2:sw=2:tw=78:expandtab:ft=rst: