И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке / Firebird, InterBase

ReSQL.ru

Мобильная версия Контакт Правила FAQ Помощь

Гость

Войти | Регистрация | Профиль | Очистить

Новые сообщения | Избранное

Форумы | Пользователи | Статистика | Мод. лог | Поиск

Цитировать

Написать

Автор*:

Ввести пароль для входа

Тема*:

Сообщение

Данное сообщение тематическое

Сообщение содержит картинки или видео 18+

Автор:

ВНИМАНИЕ! На данном подфоруме действуют строгие правила. Удостоверьтесь, что ваше сообщение соответствует им!

Форум или тема закрыты для гостей. Необходима авторизация!

Загрузить последнюю сохраненную версию

Вложение:

Вставить как галерею

Максимальный размер вложений: 4,0 МБ, аудио/видео: 8,0 МБ. Картинки большего размера ужимаются, если возможно.

Введите код, изображенный на картинке. Если код нечитаемый, кликните картинку, чтобы загрузить другой вариант.

Отправляя сообщение, я выражаю свое согласие с правилами форума и принимаю пользовательское соглашение.

Доб. в избранное | Игнор. тему | Прикреп. тему | Пометить прочит. / непрочит. | Фильтр

Форумы / Firebird, InterBase [игнор отключен] [закрыт для гостей] / И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

33 сообщений из 33, показаны все 2 страниц

все

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467545

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Intro.
Эта загадочная история началась почти год назад. Несколько раз в месяц, а затем всё чаще и чаще, юзера начали вопить: дескать, запускаем прогу, а она застревает в самом начале и возобновляет процесс загрузки только через 20-30 сек, а иногда и дольше.
Ожесточённая перестрелка Интенсивная переписка с Главным Источником Света, тестирование и накатывание нескольких патчей избавило нас в итоге от этой напасти. По крайне мерее - в продакшене.
А заодно родился небольшой shell-скрипт, названный "калибратором", который в цикле делает коннекты и регистрирует их длительность, если она превысила 1 сек. А для сверхтупых коннектов (> 10 сек) еще и строит стек-трейсы.

подробнее про этот скрипт1) кладёт в текстовый файл (его имя = 'connect_calibr.txt') значение системного времени, с точностью до ms;
2) вызывает (асинхронно) isql с указанием выполнить некоторую процедуру (её имя = sys_connect_calibrate), после чего делает ПАУЗУ в 10 сек (её смысл - см ниже, пункт 4.1).
3) процедура эта лезет в 'connect_calibr.txt' (он объявлен в базе как external-таблица и считывает оттуда время, которое было непосредственно перед вызовом isql. И сравнивает значение datediff(millisecond from <connect_calibr.txt> to <'now'>) с порогом в 1000 мс. Если значение превысило этот порог, то процедура пишет этот результат (вызова datediff()) в еще один файлик, его имя = 'too_long_connect.txt'. Затем происходит выход из isql.
4) скрипт калибратора по окончании паузы в 10 сек:
4.1) проверяет, остался ли живой процесс isql. Если да, то это значит, что коннект ДО СИХ ПОР не может установиться (за 10 сек!) и тогда калибратор вызывает создание стек-трейса для двух процессов: сервера firebird и застрявшего isql. Результаты gdb складываются в отдельные логи, ес-сно.
4.2) проверяет наличие файла 'too_long_connect.txt' (он заботливо грохает его каждый раз на шаге "1"). Если файл появился, значит коннект шел "странно долго", и это дело регистрируется в логе работы скрипта примерно так:

Код: plaintext

2013-11-16 23:06:18.6053 pure time of connect: 6372 ms, threads: 460

Ну так вот: игра с калибратором - натравливание его на базу 3.х, которая подвергается достаточно сильной DML-нагрузке, - показала, что проблема "странно долгих" коннектов в общем случае до сих пор НЕ решена.

Обнаружено две закономерности:
1) тормоза при установке коннектов всегда приходят внезапно. То есть, на итерации непосредственном перед "этим" коннект ставился менее чем за 1 сек, а на следующей итерации он вдруг заткнулся на 3-4 сек, а то и больше;
2) чем дольше работает тест с молотилками (и калибратор тоже), тем чаще встречаются затыки и, главное, тем они здоровее.

Возможно, dimitr увидел еще что-то (у него есть этот тест и он воспроизвёл эти тормоза). Я не педалирую эту проблему, т.к. Источникам Света сейчас совсем не до этого. Да и чтобы получить сей эффект, нужно и железо подходящее, и запас терпения часов на 20-30 (ладно, шутю: часов на 10-12 :)). Однако, топег всё таки открою. Т.к. стало видно хоть что-то, кроме верхушки айсберга.

Handshaking.
Источник Света, подаривший миру плагины подключений к ФБ, показал способ "визуализации" процесса установки соединения.

На консоли сервера (если он запущен как приложение, а не демон) результат успешного коннекта при этом отображается так:

Код: plaintext

1.
2.
3.
4.
5.
6.

Sat Nov 16 16:16:48 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=0 32780 32781
Sat Nov 16 16:16:48 2013: Srv: accept_connection: accepted ud=0 protocol=800c
Sat Nov 16 16:16:48 2013: Line encryption disabled on attach
Sat Nov 16 16:16:48 2013: Srv: ServerAuth()
Sat Nov 16 16:16:48 2013: Srv: ServerAuth(): user name=SYSDBA
Sat Nov 16 16:16:48 2013: Srv: authenticate: ServerAuth calls plug Legacy_Auth
Sat Nov 16 16:16:48 2013: Srv: authenticate: Ahh - success

(увы, время добавляется не самим сервером, а через supertee -t)
Когда коннекты прут со 100500 окон, то на консоли сервера будет винегрет из практически одинаковых сообщений, показанных выше.

А на консоли isql, который от собранного "по-хитрому" ФБ, процесс установки коннекта виден без всяких "помех".
И при успехе он таков:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.

Sat Nov 16 23:53:26 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sat Nov 16 23:53:26 2013: Cli: loadClnt: Loaded from PB password = 123
Sat Nov 16 23:53:26 2013: Cli: authenticateStep0(Legacy_Auth)
Sat Nov 16 23:53:26 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sat Nov 16 23:53:26 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sat Nov 16 23:53:26 2013: Cli: accepted data for plugin length=0
Sat Nov 16 23:53:26 2013: Cli: secureAuthentication
Sat Nov 16 23:53:26 2013: Cli: secureAuthentication: port OK, op=94
Sat Nov 16 23:53:26 2013: Cli: call init for DB='idx_test'
 Sat Nov 16 23:53:26 2013: Cli: init calls authFillParametersBlock 
 Sat Nov 16 23:53:26 2013: Cli: authReceiveResponse: Default answer 
Sat Nov 16 23:53:26 2013: Cli: authReceiveResponse: OK!
Sat Nov 16 23:53:26 2013: Database:  localhost/3330:idx_test, User: calibrator

Анализ логов.
Не буду сейчас грузить почтеннейшую публику, ибо поздний час, да и выходной день.
Поэтому говорю сразу: заклинивает между строками, которые выделены цветом (см выше) . Каждый раз - именно между этими двумя строками:

Код: plaintext

 Cli: init calls authFillParametersBlock 
 Cli: authReceiveResponse: Default answer

Иллюстрация (для любознательных)
Вот TOP-3 тупых коннекта, которые у мну зарегистрированы за последние 8 часов (тест стартовал в 16 мск):

Код: plaintext

1.
2.

Sat Nov 16 22:14:34 2013: 2013-11-16 22:14:34.1519 pure time of connect: 7195 ms, threads: 459
Sat Nov 16 23:06:18 2013: 2013-11-16 23:06:18.6053 pure time of connect: 6372 ms, threads: 460
Sat Nov 16 23:05:26 2013: 2013-11-16 23:05:26.2829 pure time of connect: 6363 ms, threads: 460

Лог работы калибратора для 7195 ms (сообщения "визуализации handshaking'a" показаны синим цветом, штатный вывод в isql - серым, вывод в bash'e - чёрным):

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.

Sat Nov 16 22:14:24 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i connect_calibr.sql
Sat Nov 16 22:14:24 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sat Nov 16 22:14:24 2013: Cli: loadClnt: Loaded from PB password = 123
Sat Nov 16 22:14:24 2013: Cli: authenticateStep0(Legacy_Auth)
Sat Nov 16 22:14:24 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sat Nov 16 22:14:24 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sat Nov 16 22:14:24 2013: calibrator isql pid = >>> 30406 <<<
Sat Nov 16 22:14:24 2013: check:
Sat Nov 16 22:14:24 2013: Cli: accepted data for plugin length=0
Sat Nov 16 22:14:24 2013: Cli: secureAuthentication
Sat Nov 16 22:14:24 2013: Cli: secureAuthentication: port OK, op=94
Sat Nov 16 22:14:24 2013: Cli: call init for DB='idx_test'
 Sat Nov 16 22:14:24 2013: Cli: init calls authFillParametersBlock 
Sat Nov 16 22:14:24 2013: root     30406 14030  0 34906  2492   2 22:14 pts/6    00:00:00 /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas     -role rdb$admin -n -i connect_calibr.sql
Sat Nov 16 22:14:24 2013: -----------------------------------------
Sat Nov 16 22:14:24 2013: 
Sat Nov 16 22:14:24 2013: 2013-11-16 22:14:24.1114
Sat Nov 16 22:14:24 2013: 
Sat Nov 16 22:14:24 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=30406
Sat Nov 16 22:14:24 2013: 
 Sat Nov 16 22:14:30 2013: Cli: authReceiveResponse: Default answer 
Sat Nov 16 22:14:30 2013: Cli: authReceiveResponse: OK!
Sat Nov 16 22:14:30 2013: execute procedure SYS_CONNECT_CALIBRATE;
Sat Nov 16 22:14:31 2013: Current memory = 1146194016
Sat Nov 16 22:14:31 2013: Delta memory = 1430440
Sat Nov 16 22:14:31 2013: Max memory = 1155345160
Sat Nov 16 22:14:31 2013: Elapsed time= 0.81 sec
Sat Nov 16 22:14:31 2013: Cpu = 0.00 sec
Sat Nov 16 22:14:31 2013: Buffers = 2048
Sat Nov 16 22:14:31 2013: Reads = 31685
Sat Nov 16 22:14:31 2013: Writes = 419
Sat Nov 16 22:14:31 2013: Fetches = 61111
Sat Nov 16 22:14:31 2013: set echo off;
Sat Nov 16 22:14:34 2013: 2013-11-16 22:14:34.1166
Sat Nov 16 22:14:34 2013: 
Sat Nov 16 22:14:34 2013: finish 10 seconds pause while isql in bkgr mode
Sat Nov 16 22:14:34 2013: 
Sat Nov 16 22:14:34 2013: check for call dumpEngine if isql process still alive
Sat Nov 16 22:14:34 2013:   PID TTY          TIME CMD
Sat Nov 16 22:14:34 2013: 2013-11-16 22:14:34.1519 pure time of connect: 7195 ms, threads: 459
Sat Nov 16 22:14:34 2013: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Sat Nov 16 22:14:34 2013: 20131116_221434 stopping trace session after trying to connect. . .

Лог работы калибратора для 6372 ms:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.

Sat Nov 16 23:06:08 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i connect_calibr.sql
Sat Nov 16 23:06:08 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sat Nov 16 23:06:08 2013: Cli: loadClnt: Loaded from PB password = 123
Sat Nov 16 23:06:08 2013: Cli: authenticateStep0(Legacy_Auth)
Sat Nov 16 23:06:08 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sat Nov 16 23:06:08 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sat Nov 16 23:06:08 2013: Cli: accepted data for plugin length=0
Sat Nov 16 23:06:08 2013: Cli: secureAuthentication
Sat Nov 16 23:06:08 2013: Cli: secureAuthentication: port OK, op=94
Sat Nov 16 23:06:08 2013: Cli: call init for DB='idx_test'
 Sat Nov 16 23:06:08 2013: Cli: init calls authFillParametersBlock 
Sat Nov 16 23:06:08 2013: calibrator isql pid = >>> 19497 <<<
Sat Nov 16 23:06:08 2013: check:
Sat Nov 16 23:06:08 2013: root     19497 14030  0 34906  2496   5 23:06 pts/6    00:00:00 /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas     -role rdb$admin -n -i connect_calibr.sql
Sat Nov 16 23:06:08 2013: -----------------------------------------
Sat Nov 16 23:06:08 2013: 
Sat Nov 16 23:06:08 2013: 2013-11-16 23:06:08.5596
Sat Nov 16 23:06:08 2013: 
Sat Nov 16 23:06:08 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=19497
Sat Nov 16 23:06:08 2013: 
 Sat Nov 16 23:06:13 2013: Cli: authReceiveResponse: Default answer 
Sat Nov 16 23:06:13 2013: Cli: authReceiveResponse: OK!
Sat Nov 16 23:06:13 2013: execute procedure SYS_CONNECT_CALIBRATE;
Sat Nov 16 23:06:14 2013: Current memory = 1160754880
Sat Nov 16 23:06:14 2013: Delta memory = 1991008
Sat Nov 16 23:06:14 2013: Max memory = 1177281168
Sat Nov 16 23:06:14 2013: Elapsed time= 1.11 sec
Sat Nov 16 23:06:14 2013: Cpu = 0.00 sec
Sat Nov 16 23:06:14 2013: Buffers = 2048
Sat Nov 16 23:06:14 2013: Reads = 36080
Sat Nov 16 23:06:14 2013: Writes = 440
Sat Nov 16 23:06:14 2013: Fetches = 64716
Sat Nov 16 23:06:14 2013: set echo off;
Sat Nov 16 23:06:18 2013: 2013-11-16 23:06:18.5648
Sat Nov 16 23:06:18 2013: 
Sat Nov 16 23:06:18 2013: finish 10 seconds pause while isql in bkgr mode
Sat Nov 16 23:06:18 2013: 
Sat Nov 16 23:06:18 2013: check for call dumpEngine if isql process still alive
Sat Nov 16 23:06:18 2013:   PID TTY          TIME CMD
Sat Nov 16 23:06:18 2013: 2013-11-16 23:06:18.6053 pure time of connect: 6372 ms, threads: 460

Лог работы калибратора для 6363 ms:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.

Sat Nov 16 23:05:16 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i connect_calibr.sql
Sat Nov 16 23:05:16 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sat Nov 16 23:05:16 2013: Cli: loadClnt: Loaded from PB password = 123
Sat Nov 16 23:05:16 2013: Cli: authenticateStep0(Legacy_Auth)
Sat Nov 16 23:05:16 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sat Nov 16 23:05:16 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sat Nov 16 23:05:16 2013: Cli: accepted data for plugin length=0
Sat Nov 16 23:05:16 2013: Cli: secureAuthentication
Sat Nov 16 23:05:16 2013: Cli: secureAuthentication: port OK, op=94
Sat Nov 16 23:05:16 2013: Cli: call init for DB='idx_test'
 Sat Nov 16 23:05:16 2013: Cli: init calls authFillParametersBlock 
Sat Nov 16 23:05:16 2013: calibrator isql pid = >>> 19152 <<<
Sat Nov 16 23:05:16 2013: check:
Sat Nov 16 23:05:16 2013: root     19152 14030  0 34906  2508   9 23:05 pts/6    00:00:00 /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas     -role rdb$admin -n -i connect_calibr.sql
Sat Nov 16 23:05:16 2013: -----------------------------------------
Sat Nov 16 23:05:16 2013: 
Sat Nov 16 23:05:16 2013: 2013-11-16 23:05:16.2461
Sat Nov 16 23:05:16 2013: 
Sat Nov 16 23:05:16 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=19152
Sat Nov 16 23:05:16 2013: 
 Sat Nov 16 23:05:21 2013: Cli: authReceiveResponse: Default answer 
Sat Nov 16 23:05:21 2013: Cli: authReceiveResponse: OK!
Sat Nov 16 23:05:21 2013: execute procedure SYS_CONNECT_CALIBRATE;
Sat Nov 16 23:05:22 2013: Current memory = 1171070640
Sat Nov 16 23:05:22 2013: Delta memory = 2909568
Sat Nov 16 23:05:22 2013: Max memory = 1177281168
Sat Nov 16 23:05:22 2013: Elapsed time= 1.13 sec
Sat Nov 16 23:05:22 2013: Cpu = 0.00 sec
Sat Nov 16 23:05:22 2013: Buffers = 2048
Sat Nov 16 23:05:22 2013: Reads = 34264
Sat Nov 16 23:05:22 2013: Writes = 662
Sat Nov 16 23:05:22 2013: Fetches = 64127
Sat Nov 16 23:05:22 2013: set echo off;
Sat Nov 16 23:05:26 2013: 2013-11-16 23:05:26.2514
Sat Nov 16 23:05:26 2013: 
Sat Nov 16 23:05:26 2013: finish 10 seconds pause while isql in bkgr mode
Sat Nov 16 23:05:26 2013: 
Sat Nov 16 23:05:26 2013: check for call dumpEngine if isql process still alive
Sat Nov 16 23:05:26 2013:   PID TTY          TIME CMD
Sat Nov 16 23:05:26 2013: 2013-11-16 23:05:26.2829 pure time of connect: 6363 ms, threads: 460

В общем - следите за новостями. Наверняка что-нибудь еще нарыть получится. Как знать - вдруг теперь dimitr/hvlad/alex прибьют наконец-то эту багу. Или меня... ;-)

...

Рейтинг:

0 / 0

17.11.2013, 00:28:53

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467547

Dimitry Sibiryakov

Участник

Сообщения: 54 521

Рейтинг: 0 / 0

ТаблоидВозможно, dimitr увидел еще что-то (у него есть этот тест и он воспроизвёл
эти тормоза).
Только на этой неделе он занёс в трекер два тикета, связанных с конектом. Подождал бы ты
пока он их закроет...
Posted via ActualForum NNTP Server 1.5

...

Рейтинг:

0 / 0

17.11.2013, 00:39:21

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467549

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Dimitry SibiryakovТаблоидВозможно, dimitr увидел еще что-то (у него есть этот тест и он воспроизвёл
эти тормоза).
Только на этой неделе он занёс в трекер два тикета, связанных с конектом. Подождал бы ты
пока он их закроет...как их увидеть, только чтобы не заглядывая в фб-девел ?
Вот тута: http://tracker.firebirdsql.org/secure/IssueNavigator.jspa?sorter/field=updated&sorter/order=DESC - какие-то обрывки только :-/
Да и здесь: http://tracker.firebirdsql.org/secure/IssueNavigator.jspa?sorter/field=updated&sorter/order=DESC - стопудово далеко не всё видно.

Там есть что-то типа "ленты событий", чтобы в date desc видеть ВСЕ тикеты ?

...

Рейтинг:

0 / 0

17.11.2013, 00:46:05

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467550

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

тьфу, две одинаковые ссылки запостил... в общем: искал по assignee, сначала по dimitr'у, затем по alex'у.

...

Рейтинг:

0 / 0

17.11.2013, 00:47:17

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467551

Dimitry Sibiryakov

Участник

Сообщения: 54 521

Рейтинг: 0 / 0

ТаблоидТам есть что-то типа "ленты событий", чтобы в date desc видеть ВСЕ тикеты ?

Отсортировать по номеру тикета?..
Posted via ActualForum NNTP Server 1.5

...

Рейтинг:

0 / 0

17.11.2013, 00:48:57

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467554

Гаджимурадов Рустам

Участник

Сообщения: 64 024

Рейтинг: 0 / 0

Сортировка по номеру тикета от сортировке по дате
ничем не отличается (не должна, по крайней мере).

Ты лучше не умничай, ты пальцем покажи (с) -
на этой неделе таких (созданных) тикетов нет не
только от ДЕ, но и вообще. Есть один тикет от ДЕ
про дисконнект, а не коннект.

P.S. Лента есть (browse project), поиск тоже
всё показывает (хоть и не всегда удобен).
И "занёс" - это не assignee, а "reporter".

Posted via ActualForum NNTP Server 1.5

...

Рейтинг:

0 / 0

17.11.2013, 00:55:10

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467627

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

ГРP.S. Лента есть (browse project), поиск тоже всё показываетда, я уже врубился: там фильтр был по 'unresolved', не сразу увидел.
DSдва тикета, связанных с конектомПро коннект на минувшей неделе только core-4265, но он по мотивам вот этого мультфильма.

...

Рейтинг:

0 / 0

17.11.2013, 09:16:59

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467644

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

Таблоид,

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

...

Рейтинг:

0 / 0

17.11.2013, 10:24:17

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467654

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Вот "блок" сообщений, который вываливается в консоли сервера в ответ на isql ... -user calibrator, когда НЕТ других isql'ей:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.

Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
Srv: accept_connection: creates port_srv_auth_block
Srv: accept_connection: is going to load data to port_srv_auth_block
Srv: AuthBlock: login CALIBRATOR
Srv: AuthBlock: plugin Legacy_Auth
Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
Srv: getMultiPartConnectParameter: loaded tag 7 length 11
Srv: AuthBlock: data 11
Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
Srv: accept_connection: calls createPluginsItr
Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
Srv: accept_connection: accepted ud=1 protocol=800d
Line encryption disabled on attach
Srv: ServerAuth()
Srv: ServerAuth(): user name=CALIBRATOR
Srv: ServerAuth(): miss data with tag 84

Но калибратор работает не один, там в параллели еще 450 молотилок. И вот мешанина, которая вылезает на консоли сервера в итоге:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.

Srv: AuthBlock: data 11
Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
Srv: accept_connection: calls createPluginsItr
Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
Srv: accept_connection: accepted ud=1 protocol=800d
Line encryption disabled on attach svc
Srv: ServerAuth()
Srv: ServerAuth(): user name=SYSDBA
Srv: ServerAuth(): miss data with tag 111
Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
Srv: accept_connection: creates port_srv_auth_block
Srv: accept_connection: is going to load data to port_srv_auth_block
Srv: AuthBlock: login SYSDBA
Srv: AuthBlock: plugin Legacy_Auth
Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
Srv: getMultiPartConnectParameter: loaded tag 7 length 11
Srv: AuthBlock: data 11
Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
Srv: accept_connection: calls createPluginsItr
Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
Srv: accept_connection: accepted ud=1 protocol=800d
Line encryption disabled on attach svc
Srv: ServerAuth()
Srv: ServerAuth(): user name=SYSDBA
Srv: ServerAuth(): miss data with tag 111
Srv: accept_connection: protoaccept a=1 (v>=13)=0 32780 32781
Srv: accept_connection: accepted ud=0 protocol=800c
Line encryption disabled on attach
Srv: ServerAuth()
Srv: ServerAuth(): user name=SYSDBA
Srv: authenticate: ServerAuth calls plug Legacy_Auth
Srv: authenticate: Ahh - success

Как тут понять, "от кого - чего - к чему" ?

...

Рейтинг:

0 / 0

17.11.2013, 11:00:55

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467657

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

Таблоид,

практически никак. Ибо не за тот инструмент ты взялся. Тебе (как и любому пользователю ФБ) вообще недоступны средства диагностики таких проблем.

...

Рейтинг:

0 / 0

17.11.2013, 11:19:22

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467671

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Ну, кое что дополнительно всё равно нарылось.
Все отображаемые клиентом сообщения зашиты в src/remote/client/interface.cpp.
Я добавил в него еще немного диагностического вывода (см аттач; сообщения-"добавки" имеют префикс 'nfo:' вместо 'cli:').
И получил следующий расклад для коннекта длительностью в 4 сек:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.

Sun Nov 17 11:36:27 2013: 1117_113627 trying to connect via TCP to localhost/3330:idx_test. . .
Sun Nov 17 11:36:27 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i
Sun Nov 17 11:36:27 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sun Nov 17 11:36:27 2013: Cli: loadClnt: Loaded from PB password = 123
Sun Nov 17 11:36:27 2013: Cli: authenticateStep0(Legacy_Auth)
Sun Nov 17 11:36:27 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sun Nov 17 11:36:27 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sun Nov 17 11:36:27 2013: Cli: accepted data for plugin length=0
Sun Nov 17 11:36:27 2013: Cli: secureAuthentication
Sun Nov 17 11:36:27 2013: Cli: secureAuthentication: port OK, op=94
Sun Nov 17 11:36:27 2013: Cli: call init for DB='idx_test'
Sun Nov 17 11:36:27 2013: Cli: init calls authFillParametersBlock
Sun Nov 17 11:36:27 2013: nfo: return from authFillParametersBlock
Sun Nov 17 11:36:27 2013: nfo: before send_packet(port, packet)
Sun Nov 17 11:36:27 2013: nfo: after send_packet(port, packet)
 Sun Nov 17 11:36:27 2013: nfo: authReceiveResponse: before receive_packet 
Sun Nov 17 11:36:27 2013: calibrator isql pid = >>> 6100 <<<
Sun Nov 17 11:36:27 2013: check:
Sun Nov 17 11:36:27 2013: root      6100 11585  0 34906  2476   2 11:36 pts/3    00:00:00 /opt/fb30/bin/isql localhost/33
Sun Nov 17 11:36:27 2013: -----------------------------------------
Sun Nov 17 11:36:27 2013:
Sun Nov 17 11:36:27 2013: 2013-11-17 11:36:27.2826
Sun Nov 17 11:36:27 2013:
Sun Nov 17 11:36:27 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=6100
Sun Nov 17 11:36:27 2013:
 Sun Nov 17 11:36:30 2013: nfo: authReceiveResponse: after receive_packet 
Sun Nov 17 11:36:30 2013: Cli: authReceiveResponse: Default answer
Sun Nov 17 11:36:30 2013: Cli: authReceiveResponse: OK!
Sun Nov 17 11:36:30 2013: execute procedure SYS_CONNECT_CALIBRATE;
Sun Nov 17 11:36:31 2013: Current memory = 989545224
Sun Nov 17 11:36:31 2013: Delta memory = -508680
Sun Nov 17 11:36:31 2013: Max memory = 1000571528
Sun Nov 17 11:36:31 2013: Elapsed time= 0.85 sec
Sun Nov 17 11:36:31 2013: Cpu = 0.00 sec
Sun Nov 17 11:36:31 2013: Buffers = 2048
Sun Nov 17 11:36:31 2013: Reads = 23385
Sun Nov 17 11:36:31 2013: Writes = 1035
Sun Nov 17 11:36:31 2013: Fetches = 66869
Sun Nov 17 11:36:31 2013: set echo off;
Sun Nov 17 11:36:37 2013: 2013-11-17 11:36:37.2862
Sun Nov 17 11:36:37 2013:
Sun Nov 17 11:36:37 2013: finish 10 seconds pause while isql in bkgr mode
Sun Nov 17 11:36:37 2013:
Sun Nov 17 11:36:37 2013: check for call dumpEngine if isql process still alive
Sun Nov 17 11:36:37 2013:   PID TTY          TIME CMD
Sun Nov 17 11:36:37 2013: 2013-11-17 11:36:37.3211 pure time of connect:  4004  ms, threads: 458

То есть, это вот здесь всё затыкается:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.

static void authReceiveResponse(bool havePacket, ClntAuthBlock& cBlock, rem_port* port,
        Rdb* rdb, IStatus* status, PACKET* packet, bool checkKeys)
{
        LocalStatus s;

        for (;;)
        {
                // Get response
                if (!havePacket)
                {
                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: authReceiveResponse: before receive_packet\n")); // 17.11.2013
                        receive_packet(port, packet);
                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: authReceiveResponse: after receive_packet\n")); // 17.11.2013
                }
                else
                {
                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: authReceiveResponse: before fb_assert\n")); // 17.11.2013
                        fb_assert(packet->p_operation == op_cond_accept);
                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: authReceiveResponse: after fb_assert\n")); // 17.11.2013
                }
                havePacket = false;             // havePacket means first packet is already received
. . .

...

Рейтинг:

0 / 0

17.11.2013, 12:00:40

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467709

Симонов Денис

Участник

Откуда: Рязань

Сообщения: 11 624

Рейтинг: 0 / 0

Таблоид,

не то смотришь. В выделенной тобой строчке клиент делает пересылку пакетов серверу. Собственно основная задержка либо во время самой этой пересылки (но у тебя вроде localhost), либо на сервере по обработке пересылаемого пакета, что тебе и так уже сказал dimitr

...

Рейтинг:

0 / 0

17.11.2013, 13:29:09

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467714

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Симонов Денисосновная задержка либо во время самой этой пересылки (но у тебя вроде localhost), либо на сервере по обработке пересылаемого пакета, что тебе и так уже сказал dimitrКалибратор всегда трудится на том же хосте, что и ФБ. Чтобы исключить влияние перекрученных проводов, глюкавых хабов и прочего. В базу лезет по tcp, оттого и localhost.
Я уже натолкал в функцию receive_packet_noqueue() дебаговых сообщений, с выводом номеров строк (__LINE__).
Запустил всё по-новой, те же 450 молотилок с калибратором - пущай полетают.

Пока что ТОП-10 тупых коннектов - так, мелкие рыбёшки:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.

20131117_133920 - scan log: connect_calibr_30_131117_124634.log
Sun Nov 17 13:38:32 2013: 2013-11-17 13:38:32.1824 pure time of connect: 2610 ms, threads: 458
Sun Nov 17 13:39:06 2013: 2013-11-17 13:39:06.7922 pure time of connect: 2551 ms, threads: 456
Sun Nov 17 13:38:49 2013: 2013-11-17 13:38:49.5125 pure time of connect: 2546 ms, threads: 457
Sun Nov 17 13:08:08 2013: 2013-11-17 13:08:08.5137 pure time of connect: 2468 ms, threads: 451
Sun Nov 17 13:36:13 2013: 2013-11-17 13:36:13.5481 pure time of connect: 2431 ms, threads: 458
Sun Nov 17 13:38:14 2013: 2013-11-17 13:38:14.8516 pure time of connect: 2427 ms, threads: 458
Sun Nov 17 13:09:35 2013: 2013-11-17 13:09:35.5920 pure time of connect: 2383 ms, threads: 455
Sun Nov 17 13:36:48 2013: 2013-11-17 13:36:48.2088 pure time of connect: 2381 ms, threads: 456
Sun Nov 17 13:19:25 2013: 2013-11-17 13:19:25.7167 pure time of connect: 2337 ms, threads: 453
Sun Nov 17 13:25:48 2013: 2013-11-17 13:25:48.3874 pure time of connect: 2292 ms, threads: 456

Ну так и времени прошло всего 1 час, подождать надо.

...

Рейтинг:

0 / 0

17.11.2013, 13:41:38

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467719

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Симонов Денислибо на сервере по обработке пересылаемого пакетаЕсли этот вариант, то дальше я копать не буду, тут только Монстры Рока смогут.
Но я таки подожду, пущай помолотит часов 5-6, после чего посмотрим на лог сообщений, которые генерились внутри receive_packet_noqueue().

...

Рейтинг:

0 / 0

17.11.2013, 13:45:47

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467730

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

Таблоид,

я в своих тестах долгие коннекты искал (и находил) именно внутри ядра

...

Рейтинг:

0 / 0

17.11.2013, 14:12:14

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467736

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

... посмотрел я снова в винегрет, который на серверой консоли: тихий ужос.
Вот есть несколько тупых коннектов, были зарегистрированы сегодня утром (тест молотил к тому времени примерно 16 часов):

Код: plaintext

1.
2.
3.
4.

2013-11-17 08:39:53.5759 pure time of connect: 7719 ms, threads: 460
2013-11-17 04:07:58.1606 pure time of connect: 7384 ms, threads: 460
2013-11-17 04:42:32.3439 pure time of connect: 7298 ms, threads: 460
2013-11-16 22:14:34.1519 pure time of connect: 7195 ms, threads: 459
2013-11-17 04:51:02.3839 pure time of connect: 7182 ms, threads: 459

Беру фрагмент лога вывода на сервере для первого варианта, 08:39:53.
И вижу в нём смежные сообщения с интервалом в 11 ( одиннадцать ) секунд вместо восьми:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.

08:39:43 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=0 32780 32781
08:39:43 2013: Srv: accept_connection: accepted ud=0 protocol=800c
08:39:43 2013: Line encryption disabled on attach
08:39:43 2013: Srv: ServerAuth()
08:39:43 2013: Srv: ServerAuth(): user name=SYSDBA
08:39:43 2013: Srv: authenticate: ServerAuth calls plug Legacy_Auth
08:39:43 2013: Srv: authenticate: Ahh - success
08:39:43 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
08:39:43 2013: Srv: accept_connection: creates port_srv_auth_block
08:39:43 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
08:39:43 2013: Srv: AuthBlock: login CALIBRATOR
08:39:43 2013: Srv: AuthBlock: plugin Legacy_Auth
08:39:43 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
08:39:43 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
08:39:43 2013: Srv: AuthBlock: data 11
08:39:43 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
08:39:43 2013: Srv: accept_connection: calls createPluginsItr
08:39:43 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
08:39:43 2013: Srv: accept_connection: accepted ud=1 protocol=800d
08:39:43 2013: Line encryption disabled on attach
08:39:43 2013: Srv: ServerAuth()
08:39:43 2013: Srv: ServerAuth(): user name=CALIBRATOR
 08:39:43 2013: Srv: ServerAuth(): miss data with tag 84
08:39:54 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781 
08:39:54 2013: Srv: accept_connection: creates port_srv_auth_block
08:39:54 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
08:39:54 2013: Srv: AuthBlock: login SYSDBA
08:39:54 2013: Srv: AuthBlock: plugin Legacy_Auth
08:39:54 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
08:39:54 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
08:39:54 2013: Srv: AuthBlock: data 11
08:39:54 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
08:39:54 2013: Srv: accept_connection: calls createPluginsItr
08:39:54 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
08:39:54 2013: Srv: accept_connection: accepted ud=1 protocol=800d
08:39:54 2013: Line encryption disabled on attach svc
08:39:54 2013: Srv: ServerAuth()
08:39:54 2013: Srv: ServerAuth(): user name=SYSDBA
08:39:54 2013: Srv: ServerAuth(): miss data with tag 111
08:39:54 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
08:39:54 2013: Srv: accept_connection: creates port_srv_auth_block
08:39:54 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
08:39:54 2013: Srv: AuthBlock: login SYSDBA
08:39:54 2013: Srv: AuthBlock: plugin Legacy_Auth
08:39:54 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
08:39:54 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
08:39:54 2013: Srv: AuthBlock: data 11
08:39:54 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
08:39:54 2013: Srv: accept_connection: calls createPluginsItr
08:39:54 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
08:39:54 2013: Srv: accept_connection: accepted ud=1 protocol=800d
08:39:54 2013: Line encryption disabled on attach svc
08:39:54 2013: Srv: ServerAuth()

Для второго, в 04:07:58 - опять вижу соседние сообщения с интервалом в 11 секунд:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.

04:07:47 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=0 32780 32781
04:07:47 2013: Srv: accept_connection: accepted ud=0 protocol=800c
04:07:47 2013: Line encryption disabled on attach
04:07:47 2013: Srv: ServerAuth()
04:07:47 2013: Srv: ServerAuth(): user name=SYSDBA
04:07:47 2013: Srv: authenticate: ServerAuth calls plug Legacy_Auth
04:07:47 2013: Srv: authenticate: Ahh - success
04:07:48 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
04:07:48 2013: Srv: accept_connection: creates port_srv_auth_block
04:07:48 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
04:07:48 2013: Srv: AuthBlock: login CALIBRATOR
04:07:48 2013: Srv: AuthBlock: plugin Legacy_Auth
04:07:48 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
04:07:48 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
04:07:48 2013: Srv: AuthBlock: data 11
04:07:48 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
04:07:48 2013: Srv: accept_connection: calls createPluginsItr
04:07:48 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
04:07:48 2013: Srv: accept_connection: accepted ud=1 protocol=800d
04:07:48 2013: Line encryption disabled on attach
04:07:48 2013: Srv: ServerAuth()
04:07:48 2013: Srv: ServerAuth(): user name=CALIBRATOR
 04:07:48 2013: Srv: ServerAuth(): miss data with tag 84
04:07:59 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
 04:07:59 2013: Srv: accept_connection: creates port_srv_auth_block
04:07:59 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
04:07:59 2013: Srv: AuthBlock: login SYSDBA
04:07:59 2013: Srv: AuthBlock: plugin Legacy_Auth
04:07:59 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
04:07:59 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
04:07:59 2013: Srv: AuthBlock: data 11
04:07:59 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
04:07:59 2013: Srv: accept_connection: calls createPluginsItr
04:07:59 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
04:07:59 2013: Srv: accept_connection: accepted ud=1 protocol=800d
04:07:59 2013: Line encryption disabled on attach svc
04:07:59 2013: Srv: ServerAuth()
04:07:59 2013: Srv: ServerAuth(): user name=SYSDBA
04:07:59 2013: Srv: ServerAuth(): miss data with tag 111
04:07:59 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
04:07:59 2013: Srv: accept_connection: creates port_srv_auth_block
04:07:59 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
04:07:59 2013: Srv: AuthBlock: login SYSDBA
04:07:59 2013: Srv: AuthBlock: plugin Legacy_Auth
04:07:59 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
04:07:59 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
04:07:59 2013: Srv: AuthBlock: data 11
04:07:59 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
04:07:59 2013: Srv: accept_connection: calls createPluginsItr
04:07:59 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
04:07:59 2013: Srv: accept_connection: accepted ud=1 protocol=800d
04:07:59 2013: Line encryption disabled on attach svc

И для третьего случая, - то же самое, 11 секунд:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.

04:42:22 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
04:42:22 2013: Srv: accept_connection: creates port_srv_auth_block
04:42:22 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
04:42:22 2013: Srv: AuthBlock: login CALIBRATOR
04:42:22 2013: Srv: AuthBlock: plugin Legacy_Auth
04:42:22 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
04:42:22 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
04:42:22 2013: Srv: AuthBlock: data 11
04:42:22 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
04:42:22 2013: Srv: accept_connection: calls createPluginsItr
04:42:22 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
04:42:22 2013: Srv: accept_connection: accepted ud=1 protocol=800d
04:42:22 2013: Line encryption disabled on attach
04:42:22 2013: Srv: ServerAuth()
04:42:22 2013: Srv: ServerAuth(): user name=CALIBRATOR
 04:42:22 2013: Srv: ServerAuth(): miss data with tag 84
04:42:33 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
 04:42:33 2013: Srv: accept_connection: creates port_srv_auth_block
04:42:33 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
04:42:33 2013: Srv: AuthBlock: login SYSDBA
04:42:33 2013: Srv: AuthBlock: plugin Legacy_Auth
04:42:33 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
04:42:33 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
04:42:33 2013: Srv: AuthBlock: data 11
04:42:33 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
04:42:33 2013: Srv: accept_connection: calls createPluginsItr
04:42:33 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
04:42:33 2013: Srv: accept_connection: accepted ud=1 protocol=800d
04:42:33 2013: Line encryption disabled on attach svc
04:42:33 2013: Srv: ServerAuth()
04:42:33 2013: Srv: ServerAuth(): user name=SYSDBA
04:42:33 2013: Srv: ServerAuth(): miss data with tag 111
04:42:33 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
04:42:33 2013: Srv: accept_connection: creates port_srv_auth_block
04:42:33 2013: Srv: accept_connection: is going to load data to port_srv_auth_block

Выделенные строки, ясен пень, относятся к активности РАЗНЫХ isql'ей.
И одиннадцать секунд сложились из ~восьми (которые "расшифрованы" калибратором) и ~трёх (которые потрачены непонятно на что).

Во всех случаях (не только в показанных ТОП-10) действия от калибратора на сервере завершаются вот этой строкой:

Код: plaintext

Srv: ServerAuth(): miss data with tag  84

От sysdba - могут завершаться этим же сообщением, а могут и двумя другими:

Код: plaintext

Srv: ServerAuth(): miss data with tag  111

или

Код: plaintext

authenticate: ServerAuth calls plug Legacy_Auth
authenticate: Ahh - success

Чё-то тут "не того"! Почему сообщения разные для SYSDBA, хотя ошибок в логах молотилок - НОЛЬ ?

ЗЫ. Начало сообщений в логе сервера для коннектов от SYSDBA, кстати, тоже разное бывает:

Код: plaintext

1.
2.
3.
4.
5.
6.

Srv: accept_connection: protoaccept a=1 (v>=13)=0 3278 0  32781
Srv: accept_connection: accepted ud=0 protocol=800 c 
Line encryption disabled on attach
Srv: ServerAuth()
Srv: ServerAuth(): user name=SYSDBA
Srv: authenticate: ServerAuth calls plug Legacy_Auth
Srv: authenticate: Ahh - success

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.

Srv: accept_connection: protoaccept a=1 (v>=13)=1 3278 1  32781
Srv: accept_connection: creates port_srv_auth_block
Srv: accept_connection: is going to load data to port_srv_auth_block
Srv: AuthBlock: login SYSDBA
Srv: AuthBlock: plugin Legacy_Auth
Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
Srv: getMultiPartConnectParameter: loaded tag 7 length 11
Srv: AuthBlock: data 11
Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
Srv: accept_connection: calls createPluginsItr
Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
Srv: accept_connection: accepted ud=1 protocol=800 d

Хрен его поймёт, в общем... :-)

...

Рейтинг:

0 / 0

17.11.2013, 14:33:14

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467840

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Кольцо поисков постепенно сжимается. Для коннекта, который тупил в течение 6062 мс, в консоли клиента получены следующие метки времени по операциям внутри функции receive_packet_noqueue():

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
83.
84.
85.
86.
87.
88.
89.
90.
91.
92.
93.
94.
95.
96.
97.
98.
99.
100.
101.
102.
103.
104.
105.
106.
107.
108.
109.
110.
111.
112.
113.
114.
115.
116.
117.
118.
119.
120.
121.
122.
123.
124.
125.
126.
127.
128.
129.
130.
131.

Sun Nov 17 17:10:13 2013: 1117_171013 trying to connect via TCP to localhost/3330:idx_test. . .
Sun Nov 17 17:10:13 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i connect_calibr.sql
Sun Nov 17 17:10:13 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sun Nov 17 17:10:13 2013: Cli: loadClnt: Loaded from PB password = 123
Sun Nov 17 17:10:13 2013: Cli: authenticateStep0(Legacy_Auth)
Sun Nov 17 17:10:13 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sun Nov 17 17:10:13 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sun Nov 17 17:10:13 2013: Cli: accepted data for plugin length=0
Sun Nov 17 17:10:13 2013: Cli: secureAuthentication
Sun Nov 17 17:10:13 2013: Cli: secureAuthentication: port OK, op=94
Sun Nov 17 17:10:13 2013: Cli: call init for DB='idx_test'
Sun Nov 17 17:10:13 2013: Cli: init calls authFillParametersBlock
Sun Nov 17 17:10:13 2013: nfo: return from authFillParametersBlock
Sun Nov 17 17:10:13 2013: nfo: before send_packet(port, packet)
Sun Nov 17 17:10:13 2013: nfo: after send_packet(port, packet)
Sun Nov 17 17:10:13 2013: nfo: authReceiveResponse: before receive_packet
Sun Nov 17 17:10:13 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:13 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:13 2013: nfo: receive_packet_noqueue() - 6677
 Sun Nov 17 17:10:13 2013: nfo: receive_packet_noqueue() - 6763 
Sun Nov 17 17:10:13 2013: calibrator isql pid = >>> 25501 <<<
Sun Nov 17 17:10:13 2013: check:
Sun Nov 17 17:10:13 2013: root     25501 12132  0 34906  2484   0 17:10 pts/3    00:00:00 /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas     -role rdb$admin -n -i connect_calibr.sql
Sun Nov 17 17:10:13 2013: -----------------------------------------
Sun Nov 17 17:10:13 2013: 
Sun Nov 17 17:10:13 2013: 2013-11-17 17:10:13.5480
Sun Nov 17 17:10:13 2013: 
Sun Nov 17 17:10:13 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=25501
Sun Nov 17 17:10:13 2013: 
 Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - bye, 6765 
Sun Nov 17 17:10:17 2013: nfo: authReceiveResponse: after receive_packet
Sun Nov 17 17:10:17 2013: Cli: authReceiveResponse: Default answer
Sun Nov 17 17:10:17 2013: Cli: authReceiveResponse: OK!
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:17 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:18 2013: execute procedure SYS_CONNECT_CALIBRATE;
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:18 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: Current memory = 1119765824
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: Delta memory = 2876048
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: Max memory = 1126878584
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: Elapsed time= 1.65 sec
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: Cpu = 0.00 sec
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6680
Sun Nov 17 17:10:19 2013: Buffers = 2048
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6682
Sun Nov 17 17:10:19 2013: Reads = 43505
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6698
Sun Nov 17 17:10:19 2013: Writes = 681
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6701
Sun Nov 17 17:10:19 2013: Fetches = 88035
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6704
Sun Nov 17 17:10:19 2013: set echo off;
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6706
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6711
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6713
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6750
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6752
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6756
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6758
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6760
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6680
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6682
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6698
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6701
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6704
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6706
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6711
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6713
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6750
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6752
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6756
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6758
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6760
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
 Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:23 2013: 2013-11-17 17:10:23.5525   -- это уже вывод внутри isql; на что ушло 4 сек - хз :( 
Sun Nov 17 17:10:23 2013: 
Sun Nov 17 17:10:23 2013: finish 10 seconds pause while isql in bkgr mode
Sun Nov 17 17:10:23 2013: 
Sun Nov 17 17:10:23 2013: check for call dumpEngine if isql process still alive
Sun Nov 17 17:10:23 2013:   PID TTY          TIME CMD
Sun Nov 17 17:10:23 2013: 2013-11-17 17:10:23.5832 pure time of connect: 6062 ms, threads: 460

Первый "проблемный лаг", в 4 секунды (17:10:13. . .17:10:17), соотв-вует вот этому коду:

Код: plaintext

1.
2.
3.
4.
5.

  6761                  }
  6762          }
  6763          HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
   6764          receive_packet_with_callback(port, packet); 
  6765          HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - bye, %d\n", __LINE__)); // 17.11.2013
  6766  }

Что там тупило во втором лаге (17:10:19. . . 17:10:23) - непонятно, но вроде бы там ВЫХОД из isql'я происходит.
В аттаче - "пронумерованная" по строкам функция receive_packet_noqueue().

Посмотрим-ка теперь на receive_packet_with_callback() поближе...

...

Рейтинг:

0 / 0

17.11.2013, 17:43:38

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467881

NickDee

Участник

Сообщения: 1 395

Рейтинг: 0 / 0

ТаблоидВот "блок" сообщений, который вываливается в консоли сервера в ответ на isql ... -user calibrator, когда НЕТ других isql'ей:
.................
.................
.................
Как тут понять, "от кого - чего - к чему" ?
Нужно какой-нибудь идентификатор коннекта туда вывести (хоть автоинкрементальный), и станет уже разбираемо.

...

Рейтинг:

0 / 0

17.11.2013, 19:05:08

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467883

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

NickDeeНужно какой-нибудь идентификатор коннекта туда вывести (хоть автоинкрементальный), и станет уже разбираемо.они (srv: & cli:) когда руки трясут друг другу, то ИД коннекта нету еще. Что действительно было бы гут, это если бы клиент первым же пакетом отсылал на сервер что-то типа UUID, и дальше чтобы все сообщения процесса рукопожатия снабжались этим префиксом, а не просто 'srv:'.

...

Рейтинг:

0 / 0

17.11.2013, 19:07:40

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467978

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Верёвка вьётся долго, "преступник" заметает следы. Я тут нарыл кое-что, но дальше нужна помощь Источников Света (наверное).
Сейчас калибратор зафиксирован несколько коннектов тупизной примерно в 7 сек.
Я взял наугад один, который устанавливался 6798 ms.

И вижу в логе калибратора:

Код: plaintext

Sun Nov 17 20:16:13 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i connect_calibr.sql
Sun Nov 17 20:16:13 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sun Nov 17 20:16:13 2013: Cli: loadClnt: Loaded from PB password = 123
Sun Nov 17 20:16:13 2013: Cli: authenticateStep0(Legacy_Auth)
Sun Nov 17 20:16:13 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sun Nov 17 20:16:13 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Sun Nov 17 20:16:13 2013: Cli: accepted data for plugin length=0
Sun Nov 17 20:16:13 2013: Cli: secureAuthentication
Sun Nov 17 20:16:13 2013: Cli: secureAuthentication: port OK, op=94
Sun Nov 17 20:16:13 2013: Cli: call init for DB='idx_test'
Sun Nov 17 20:16:13 2013: Cli: init calls authFillParametersBlock
Sun Nov 17 20:16:13 2013: nfo: return from authFillParametersBlock
Sun Nov 17 20:16:13 2013: nfo: before send_packet(port, packet)
Sun Nov 17 20:16:13 2013: nfo: after send_packet(port, packet)
Sun Nov 17 20:16:13 2013: nfo: authReceiveResponse: before receive_packet
 Sun Nov 17 20:16:13 2013: nfo: receive_packet_with_callback() - intro, 6606 
Sun Nov 17 20:16:13 2013: calibrator isql pid = >>> 12953 <<<
Sun Nov 17 20:16:13 2013: check:
Sun Nov 17 20:16:13 2013: root     12953  3668  0 34906  2484   0 20:16 pts/3    00:00:00 /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas     -role rdb$admin -n -i connect_calibr.sql
Sun Nov 17 20:16:13 2013: -----------------------------------------
Sun Nov 17 20:16:13 2013: 
Sun Nov 17 20:16:13 2013: 2013-11-17 20:16:13.5361
Sun Nov 17 20:16:13 2013: 
Sun Nov 17 20:16:13 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=12953
Sun Nov 17 20:16:13 2013: 
 Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
Sun Nov 17 20:16:19 2013: nfo: authReceiveResponse: after receive_packet
Sun Nov 17 20:16:19 2013: Cli: authReceiveResponse: Default answer
Sun Nov 17 20:16:19 2013: Cli: authReceiveResponse: OK!
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:19 2013: execute procedure SYS_CONNECT_CALIBRATE;
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:19 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: Current memory = 1109248064
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: Delta memory = 2978320
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: Max memory = 1127232024
Sun Nov 17 20:16:20 2013: Elapsed time= 1.22 sec
Sun Nov 17 20:16:20 2013: Cpu = 0.00 sec
Sun Nov 17 20:16:20 2013: Buffers = 2048
Sun Nov 17 20:16:20 2013: Reads = 34776
Sun Nov 17 20:16:20 2013: Writes = 617
Sun Nov 17 20:16:20 2013: Fetches = 64702
Sun Nov 17 20:16:20 2013: set echo off;
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - intro, 6606
 Sun Nov 17 20:16:20 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
-- строка ниже есть вывод в консоли bash-скрипта, так что лаг в три сек тут показывает
-- разве что время дисконнекта; это сейчас НЕ интересно:
 Sun Nov 17 20:16:23 2013: 2013-11-17 20:16:23.5397 
Sun Nov 17 20:16:23 2013: 
Sun Nov 17 20:16:23 2013: finish 10 seconds pause while isql in bkgr mode
Sun Nov 17 20:16:23 2013: 
Sun Nov 17 20:16:23 2013: check for call dumpEngine if isql process still alive
Sun Nov 17 20:16:23 2013:   PID TTY          TIME CMD
Sun Nov 17 20:16:23 2013: 2013-11-17 20:16:23.5718 pure time of connect: 6798 ms, threads: 459

А теперь смотрим на эту крохотную функцию и соотв-щие номера строк (6606 и 6649):

Код: plaintext

  6589	static void receive_packet_with_callback(rem_port* port, PACKET* packet)
  6590	{
  6591	/**************************************
  6592	 *
  6593	 *	r e c e i v e _ p a c k e t _ w i t h _ c a l l b a c k
  6594	 *
  6595	 **************************************
  6596	 *
  6597	 * Functional description
  6598	 *	If received packet is request from callback info from user,
  6599	 *	send requested info (or no data if callback is not set) and
  6600	 *	wait for next packet.
  6601	 *
  6602	 **************************************/
  6603	
  6604		for (;;)
  6605		{
   6606			HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - intro, %d\n", __LINE__)); // 17.11.2013 
  6607			if (! port->receive(packet) )
  6608			{
  6609				HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6610				Arg::Gds(isc_net_read_err).raise();
  6611				HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6612			}
  6613	
  6614			switch (packet->p_operation)
  6615			{
  6616			case op_crypt_key_callback:
  6617				{
  6618					P_CRYPT_CALLBACK* cc = &packet->p_cc;
  6619					UCharBuffer buf;
  6620	
  6621					if (port->port_client_crypt_callback)
  6622					{
  6623						if (cc->p_cc_reply <= 0)
  6624						{
  6625							cc->p_cc_reply = 1;
  6626						}
  6627						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6628						UCHAR* reply = buf.getBuffer(cc->p_cc_reply);
  6629						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6630						unsigned l = port->port_client_crypt_callback->callback(cc->p_cc_data.cstr_length,
  6631							cc->p_cc_data.cstr_address, cc->p_cc_reply, reply);
  6632						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6633						cc->p_cc_data.cstr_length = l;
  6634						cc->p_cc_data.cstr_address = reply;
  6635					}
  6636					else
  6637					{
  6638						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6639						cc->p_cc_data.cstr_length = 0;
  6640					}
  6641					cc->p_cc_data.cstr_allocated = 0;
  6642	
  6643					HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6644					port->send(packet);
  6645					HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6646				}
  6647				break;
  6648			default:
   6649				HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - bye-1, %d\n", __LINE__)); // 17.11.2013 
  6650				return;
  6651			}
  6652		}
  6653		HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - bye, %d\n", __LINE__)); // 17.11.2013

Между этими двумя строками возникает затык в шесть секунд. В то, что затык возникает на switch (packet->p_operation) и поиске второго по счету "попадания" (в ветку default), я не верю.
Остаётся одно: это вызов port->receive(packet) , который в строке 6607 .

Что это за функция и в где её код - я тут "русский не понимать". Указатель rem_port* port приходит через параметры из хрен знает откуда.

...

Рейтинг:

0 / 0

17.11.2013, 22:36:01

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467982

hvlad

Участник

Сообщения: 13 125

Рейтинг: 0 / 0

Тебе же говорили, что проблема не в клиенте.
receive ждёт ответа от сервера, и клиент на это никак повлиять не может

...

Рейтинг:

0 / 0

17.11.2013, 22:43:44

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38467993

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

hvlad, вот что вижу в консоли сервера за период 20:16:13. . .20:16:24

Код: plaintext

 1+ Sun Nov 17 20:16:13 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
  Sun Nov 17 20:16:13 2013: Srv: accept_connection: creates port_srv_auth_block
  Sun Nov 17 20:16:13 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
  Sun Nov 17 20:16:13 2013: Srv: AuthBlock: login CALIBRATOR
  Sun Nov 17 20:16:13 2013: Srv: AuthBlock: plugin Legacy_Auth
  Sun Nov 17 20:16:13 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
  Sun Nov 17 20:16:13 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
  Sun Nov 17 20:16:13 2013: Srv: AuthBlock: data 11
  Sun Nov 17 20:16:13 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
  Sun Nov 17 20:16:13 2013: Srv: accept_connection: calls createPluginsItr
  Sun Nov 17 20:16:13 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
  Sun Nov 17 20:16:13 2013: Srv: accept_connection: accepted ud=1 protocol=800d
  Sun Nov 17 20:16:13 2013: Line encryption disabled on attach
  Sun Nov 17 20:16:13 2013: Srv: ServerAuth()
  Sun Nov 17 20:16:13 2013: Srv: ServerAuth(): user name=CALIBRATOR
 1- Sun Nov 17 20:16:13 2013: Srv: ServerAuth(): miss data with tag 84
 2+ Sun Nov 17 20:16:14 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=0 32780 32781
  Sun Nov 17 20:16:14 2013: Srv: accept_connection: accepted ud=0 protocol=800c
  Sun Nov 17 20:16:14 2013: Line encryption disabled on attach
  Sun Nov 17 20:16:14 2013: Srv: ServerAuth()
  Sun Nov 17 20:16:14 2013: Srv: ServerAuth(): user name=SYSDBA
  Sun Nov 17 20:16:14 2013: Srv: authenticate: ServerAuth calls plug Legacy_Auth
 2- Sun Nov 17 20:16:14 2013: Srv: authenticate: Ahh - success
 3+ Sun Nov 17 20:16:24 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
  Sun Nov 17 20:16:24 2013: Srv: accept_connection: creates port_srv_auth_block
  Sun Nov 17 20:16:24 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
  Sun Nov 17 20:16:24 2013: Srv: AuthBlock: login SYSDBA
  Sun Nov 17 20:16:24 2013: Srv: AuthBlock: plugin Legacy_Auth
  Sun Nov 17 20:16:24 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
  Sun Nov 17 20:16:24 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
  Sun Nov 17 20:16:24 2013: Srv: AuthBlock: data 11
  Sun Nov 17 20:16:24 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
  Sun Nov 17 20:16:24 2013: Srv: accept_connection: calls createPluginsItr
  Sun Nov 17 20:16:24 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
  Sun Nov 17 20:16:24 2013: Srv: accept_connection: accepted ud=1 protocol=800d
  Sun Nov 17 20:16:24 2013: Line encryption disabled on attach svc
  Sun Nov 17 20:16:24 2013: Srv: ServerAuth()
  Sun Nov 17 20:16:24 2013: Srv: ServerAuth(): user name=SYSDBA
 3- Sun Nov 17 20:16:24 2013: Srv: ServerAuth(): miss data with tag 111
. . .
// дальше идут только блоки сообщений, относящиеся к молотилкам, все они - SYSDBA
// строки с упоминанием калибратора появляются только в 20:16:30:
Sun Nov 17 20:16:30 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
Sun Nov 17 20:16:30 2013: Srv: accept_connection: creates port_srv_auth_block
Sun Nov 17 20:16:30 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
Sun Nov 17 20:16:30 2013: Srv: AuthBlock: login CALIBRATOR
Sun Nov 17 20:16:30 2013: Srv: AuthBlock: plugin Legacy_Auth
Sun Nov 17 20:16:30 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
Sun Nov 17 20:16:30 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
Sun Nov 17 20:16:30 2013: Srv: AuthBlock: data 11
Sun Nov 17 20:16:30 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
Sun Nov 17 20:16:30 2013: Srv: accept_connection: calls createPluginsItr
Sun Nov 17 20:16:30 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
Sun Nov 17 20:16:30 2013: Srv: accept_connection: accepted ud=1 protocol=800d
Sun Nov 17 20:16:30 2013: Line encryption disabled on attach
Sun Nov 17 20:16:30 2013: Srv: ServerAuth()
Sun Nov 17 20:16:30 2013: Srv: ServerAuth(): user name=CALIBRATOR
Sun Nov 17 20:16:30 2013: Srv: ServerAuth(): miss data with tag 84

Строки в диапазонах, отмеченных маркерами "1+". . ."1-" - это ответ сервера на запрос калибратора. Он всегда заканчивается фразой "Srv: ServerAuth(): miss data with tag 84", я уже наизусть этот текст знаю :-)
Следующее упоминание калибратора видим только в 20:16:30, то есть слишком "далеко" от 20:16:13, и по первой же строке ("Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781") видим, что это уже деяния от ДРУГОЙ итерации bash-скрипта, т.е. от следующего вызова isql. Это значит, что строки между "1+". . ."1-" - это ПОЛНЫЙ перечень действий сервера в ответ на просьбу установить коннект.

Строки в диапазонах "2+". . ."2-" и "3+". . ."3-"Строки в диапазонах "2+". . ."2-" и "3+". . ."3-" - это сервер занимается уже коннектами молотилок, они идут все из-под SYSDBA. Эти строки ("от sysdba") бывают двух видов, оттого и два цвета. Чем они отличаются визуально - хорошо видно по тексту и числу строк. А чем они отличаются на самом деле - не понятно, ну да и фиг с ними.

Ну так вот: обрати внимание на время, которое относится к обслуживанию запроса от CALIBRATOR'a. Это время тут ограничено СТРОГО лимитом одной секунды, 20:16: 13 .
А теперь взгляни еще раз на дырку в 6 секунд, показанную двумя постами выше , под спойлером.

Как так получается: клиент ждал "чего-то там" шесть сек, с 20:16:13 по 20:16:19, а судя по сообщениям на консоли сервера, "забота" об этом клиенте пропала уже в 20:16:13 (см метку "1-") ?

...

Рейтинг:

0 / 0

17.11.2013, 23:05:31

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468002

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

Вот еще пример, коннект почти в 9 сек.

Лог на консоли сервера:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.

 1+ Sun Nov 17 23:01:44 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
  Sun Nov 17 23:01:44 2013: Srv: accept_connection: creates port_srv_auth_block
  Sun Nov 17 23:01:44 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
  Sun Nov 17 23:01:44 2013: Srv: AuthBlock: login CALIBRATOR
  Sun Nov 17 23:01:44 2013: Srv: AuthBlock: plugin Legacy_Auth
  Sun Nov 17 23:01:44 2013: Srv: AuthBlock: plugin list Legacy_Auth,Srp,Win_Sspi
  Sun Nov 17 23:01:44 2013: Srv: getMultiPartConnectParameter: loaded tag 7 length 11
  Sun Nov 17 23:01:44 2013: Srv: AuthBlock: data 11
  Sun Nov 17 23:01:44 2013: Srv: accept_connection: finished with port_srv_auth_block prepare, a=1
  Sun Nov 17 23:01:44 2013: Srv: accept_connection: calls createPluginsItr
  Sun Nov 17 23:01:44 2013: Srv: accept_connection: client plugin='Legacy_Auth' server='Legacy_Auth'
  Sun Nov 17 23:01:44 2013: Srv: authenticate: Ahh - success
  Sun Nov 17 23:01:44 2013: Srv: accept_connection: accepted ud=1 protocol=800d
  Sun Nov 17 23:01:44 2013: Line encryption disabled on attach
  Sun Nov 17 23:01:44 2013: Srv: ServerAuth()
  Sun Nov 17 23:01:44 2013: Srv: ServerAuth(): user name=CALIBRATOR
 1- Sun Nov 17 23:01:44 2013: Srv: ServerAuth(): miss data with tag 84
2+Sun Nov 17 23:01:54 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=0 32780 32781
  Sun Nov 17 23:01:54 2013: Srv: accept_connection: accepted ud=0 protocol=800c
  Sun Nov 17 23:01:54 2013: Line encryption disabled on attach
  Sun Nov 17 23:01:54 2013: Srv: ServerAuth()
  Sun Nov 17 23:01:54 2013: Srv: ServerAuth(): user name=SYSDBA
  Sun Nov 17 23:01:54 2013: Srv: authenticate: ServerAuth calls plug Legacy_Auth
2-Sun Nov 17 23:01:54 2013: Srv: authenticate: Ahh - success
. . .
Sun Nov 17 23:02:01 2013: Srv: accept_connection: protoaccept a=1 (v>=13)=1 32781 32781
Sun Nov 17 23:02:01 2013: Srv: accept_connection: creates port_srv_auth_block
Sun Nov 17 23:02:01 2013: Srv: accept_connection: is going to load data to port_srv_auth_block
Sun Nov 17 23:02:01 2013: Srv: AuthBlock: login CALIBRATOR
Sun Nov 17 23:02:01 2013: Srv: AuthBlock: plugin Legacy_Auth

Все сообщения, относящиеся к проблемному случаю установки коннекта калибратором, на консоли сервера начинаются и заканчиваются в течение одной секунды, 23:01:44.

Тогда как лог клиента гораздо более информативен:

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.

Sun Nov 17 23:01:44 2013: /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas 123 -role rdb$admin -n -i connect_calibr.sql
Sun Nov 17 23:01:44 2013: Cli: loadClnt: Loaded from PB user = calibrator
Sun Nov 17 23:01:44 2013: Cli: loadClnt: Loaded from PB password = 123
Sun Nov 17 23:01:44 2013: Cli: authenticateStep0(Legacy_Auth)
Sun Nov 17 23:01:44 2013: Cli: extractDataFromPluginTo: userName=CALIBRATOR
Sun Nov 17 23:01:44 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
. . .
Sun Nov 17 23:01:44 2013: nfo: authReceiveResponse: before receive_packet
Sun Nov 17 23:01:44 2013: nfo: receive_packet_with_callback() - intro, 6606
Sun Nov 17 23:01:44 2013: calibrator isql pid = >>> 17075 <<<
Sun Nov 17 23:01:44 2013: check:
Sun Nov 17 23:01:44 2013: root     17075  3668  0 34906  2496   2 23:01 pts/3    00:00:00 /opt/fb30/bin/isql localhost/3330:idx_test -nod -user calibrator -pas     -role rdb$admin -n -i connect_calibr.sql
Sun Nov 17 23:01:44 2013: -----------------------------------------
Sun Nov 17 23:01:44 2013: 
Sun Nov 17 23:01:44 2013: 2013-11-17 23:01:44.2688
Sun Nov 17 23:01:44 2013: 
Sun Nov 17 23:01:44 2013: take >>> 10 <<< seconds pause while isql in bkgr mode, isqlproc=17075
Sun Nov 17 23:01:44 2013: 
Sun Nov 17 23:01:51 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Sun Nov 17 23:01:51 2013: nfo: authReceiveResponse: after receive_packet
Sun Nov 17 23:01:51 2013: Cli: authReceiveResponse: Default answer
Sun Nov 17 23:01:51 2013: Cli: authReceiveResponse: OK!

В общем, вопрос простой: если клиент чего-то там томительно ждёт почти 10 сек, и - главное! - успешно дожидается и завершает установку коннекта, то почему это не отражается в консоли сервера ?

...

Рейтинг:

0 / 0

17.11.2013, 23:21:30

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468092

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

dimitrя в своих тестах долгие коннекты искал (и находил) именно внутри ядра Тогда долгий коннект должен был бы возникать и для любой другой базы на этом хосте, если в этот момент времени идёт молотьба с "основной" тестовой базейкой.
Но это не так. Я сейчас проверил по нескольку раз скорость отклика при handshaking'e в isql - как для нагружаемой (уже более 12 часов) idx_test, так и на другой базе, к которой вообще нет коннектов.
ИТОГО: затыки есть при коннекте только к той базе, которая сейчас нагружена молотилками.
Лог сообщений в isql для не нагруженной базы:

всё укладывается менее чем в 1 сек

Код: plaintext

Mon Nov 18 06:05:04 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:05:04 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:05:04 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:05:04 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:05:04 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:05:04 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:05:04 2013: Cli: secureAuthentication
Mon Nov 18 06:05:04 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:05:04 2013: Cli: call init for DB='sqlex'
Mon Nov 18 06:05:04 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:05:04 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:05:04 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:05:04 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:05:04 2013: nfo: authReceiveResponse: before receive_packet
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:04 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:05:04 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:05:04 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:04 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:05:49 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:05:49 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:05:49 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:05:49 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:05:49 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:05:49 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:05:49 2013: Cli: secureAuthentication
Mon Nov 18 06:05:49 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:05:49 2013: Cli: call init for DB='sqlex'
Mon Nov 18 06:05:49 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:05:49 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:05:49 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:05:49 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:05:49 2013: nfo: authReceiveResponse: before receive_packet
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:49 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:05:49 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:05:49 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:05:49 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:06:03 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:06:03 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:06:03 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:06:03 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:06:03 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:06:03 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:06:03 2013: Cli: secureAuthentication
Mon Nov 18 06:06:03 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:06:03 2013: Cli: call init for DB='sqlex'
Mon Nov 18 06:06:03 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:06:03 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:06:03 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:06:03 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:06:03 2013: nfo: authReceiveResponse: before receive_packet
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:03 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:06:03 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:06:03 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:03 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:06:21 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:06:21 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:06:21 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:06:21 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:06:21 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:06:21 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:06:21 2013: Cli: secureAuthentication
Mon Nov 18 06:06:21 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:06:21 2013: Cli: call init for DB='sqlex'
Mon Nov 18 06:06:21 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:06:21 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:06:21 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:06:21 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:06:21 2013: nfo: authReceiveResponse: before receive_packet
Mon Nov 18 06:06:21 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:22 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:06:22 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:06:22 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:22 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:06:31 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:06:31 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:06:31 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:06:31 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:06:31 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:06:31 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:06:31 2013: Cli: secureAuthentication
Mon Nov 18 06:06:31 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:06:31 2013: Cli: call init for DB='sqlex'
Mon Nov 18 06:06:31 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:06:31 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:06:31 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:06:31 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:06:31 2013: nfo: authReceiveResponse: before receive_packet
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:31 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:06:31 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:06:31 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:06:31 2013: nfo: receive_packet_with_callback() - bye-1, 6649

Аналогичный лог для базы, которую долбят 450 молотилок вкупе с калибратором:

4 сек на port->receive(packet)

Код: plaintext

Mon Nov 18 06:07:12 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:07:12 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:07:12 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:07:12 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:07:12 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:07:12 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:07:12 2013: Cli: secureAuthentication
Mon Nov 18 06:07:12 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:07:12 2013: Cli: call init for DB='idx_test'
Mon Nov 18 06:07:12 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:07:12 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:07:12 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:07:12 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:07:12 2013: nfo: authReceiveResponse: before receive_packet
Mon Nov 18  06:07:12 2013: nfo: receive_packet_with_callback() - intro, 6606 
Mon Nov 18  06:07:16 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
Mon Nov 18 06:07:16 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:07:16 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:07:16 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:07:16 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:16 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:07:16 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:17 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:07:17 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:17 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:07:17 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:17 2013: nfo: receive_packet_with_callback() - bye-1, 6649
--------
Mon Nov 18 06:07:36 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:07:36 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:07:36 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:07:36 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:07:36 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:07:36 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:07:36 2013: Cli: secureAuthentication
Mon Nov 18 06:07:36 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:07:36 2013: Cli: call init for DB='idx_test'
Mon Nov 18 06:07:36 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:07:36 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:07:36 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:07:36 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:07:36 2013: nfo: authReceiveResponse: before receive_packet
 Mon Nov 18 06:07:36 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:40 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
Mon Nov 18 06:07:40 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:07:40 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:07:40 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:07:40 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:40 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:07:40 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:41 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:07:41 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:41 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:07:41 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:07:41 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:08:08 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:08:08 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:08:08 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:08:08 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:08:08 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:08:08 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:08:08 2013: Cli: secureAuthentication
Mon Nov 18 06:08:08 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:08:08 2013: Cli: call init for DB='idx_test'
Mon Nov 18 06:08:08 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:08:08 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:08:08 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:08:08 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:08:08 2013: nfo: authReceiveResponse: before receive_packet
 Mon Nov 18 06:08:08 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:12 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
Mon Nov 18 06:08:12 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:08:12 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:08:12 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:08:12 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:12 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:08:12 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:13 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:08:13 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:13 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:08:13 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:13 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:08:34 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:08:34 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:08:34 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:08:34 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:08:34 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:08:34 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:08:34 2013: Cli: secureAuthentication
Mon Nov 18 06:08:34 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:08:34 2013: Cli: call init for DB='idx_test'
Mon Nov 18 06:08:34 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:08:34 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:08:34 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:08:34 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:08:34 2013: nfo: authReceiveResponse: before receive_packet
 Mon Nov 18 06:08:34 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
Mon Nov 18 06:08:38 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:08:38 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:08:38 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:08:38 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:08:39 2013: nfo: receive_packet_with_callback() - bye-1, 6649
-------
Mon Nov 18 06:08:56 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
Mon Nov 18 06:08:56 2013: Cli: loadClnt: Loaded from PB password = masterke
Mon Nov 18 06:08:56 2013: Cli: authenticateStep0(Legacy_Auth)
Mon Nov 18 06:08:56 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
Mon Nov 18 06:08:56 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
Mon Nov 18 06:08:56 2013: Cli: accepted data for plugin length=0
Mon Nov 18 06:08:56 2013: Cli: secureAuthentication
Mon Nov 18 06:08:56 2013: Cli: secureAuthentication: port OK, op=94
Mon Nov 18 06:08:56 2013: Cli: call init for DB='idx_test'
Mon Nov 18 06:08:56 2013: Cli: init calls authFillParametersBlock
Mon Nov 18 06:08:56 2013: nfo: return from authFillParametersBlock
Mon Nov 18 06:08:56 2013: nfo: before send_packet(port, packet)
Mon Nov 18 06:08:56 2013: nfo: after send_packet(port, packet)
Mon Nov 18 06:08:56 2013: nfo: authReceiveResponse: before receive_packet
 Mon Nov 18 06:08:56 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - bye-1, 6649 
Mon Nov 18 06:09:00 2013: nfo: authReceiveResponse: after receive_packet
Mon Nov 18 06:09:00 2013: Cli: authReceiveResponse: Default answer
Mon Nov 18 06:09:00 2013: Cli: authReceiveResponse: OK!
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - bye-1, 6649
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - intro, 6606
Mon Nov 18 06:09:00 2013: nfo: receive_packet_with_callback() - bye-1, 6649

ЗЫ. Затык в несколько секунд - не обязательно единственный, как в вышеприведенных фрагментах. Первый вызов port->receive() может заклинивать на и 5..6 сек, а последующие тоже могут "подклинивать":

6 сек + 3 сек

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.

06:25:14 2013: Cli: loadClnt: Loaded from PB user = SYSDBA
06:25:14 2013: Cli: loadClnt: Loaded from PB password = masterke
06:25:14 2013: Cli: authenticateStep0(Legacy_Auth)
06:25:14 2013: Cli: extractDataFromPluginTo: userName=SYSDBA
06:25:14 2013: Cli: extractDataFromPluginTo: pluginName=Legacy_Auth
06:25:14 2013: Cli: accepted data for plugin length=0
06:25:14 2013: Cli: secureAuthentication
06:25:14 2013: Cli: secureAuthentication: port OK, op=94
06:25:14 2013: Cli: call init for DB='idx_test'
06:25:14 2013: Cli: init calls authFillParametersBlock
06:25:14 2013: nfo: return from authFillParametersBlock
06:25:14 2013: nfo: before send_packet(port, packet)
06:25:14 2013: nfo: after send_packet(port, packet)
06:25:14 2013: nfo: authReceiveResponse: before receive_packet
 06:25:14 2013: nfo: receive_packet_with_callback() - intro, 6606
06:25:18 2013: nfo: receive_packet_with_callback() - bye-1, 6649
 06:25:18 2013: nfo: authReceiveResponse: after receive_packet
06:25:18 2013: Cli: authReceiveResponse: Default answer
06:25:18 2013: Cli: authReceiveResponse: OK!
06:25:18 2013: nfo: receive_packet_with_callback() - intro, 6606
06:25:18 2013: nfo: receive_packet_with_callback() - bye-1, 6649
06:25:18 2013: nfo: receive_packet_with_callback() - intro, 6606
06:25:18 2013: nfo: receive_packet_with_callback() - bye-1, 6649
06:25:18 2013: nfo: receive_packet_with_callback() - intro, 6606
06:25:18 2013: nfo: receive_packet_with_callback() - bye-1, 6649
 06:25:18 2013: nfo: receive_packet_with_callback() - intro, 6606
06:25:21 2013: nfo: receive_packet_with_callback() - bye-1, 6649

Как показать время с большей точностью в линухе - увы, не знаю. Два лаптя по карте, блин... :(

...

Рейтинг:

0 / 0

18.11.2013, 06:31:06

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468102

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

ПолуОФФ.
Интересное кино получается, когда isql показывает статистику: чересполосица какая-то :-)

isql output

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.

Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6763
Sun Nov 17 17:10:19 2013: Current memory = 1119765824
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - bye, 6765
Sun Nov 17 17:10:19 2013: Delta memory = 2876048
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - intro, 6671
Sun Nov 17 17:10:19 2013: Max memory = 1126878584
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6673
Sun Nov 17 17:10:19 2013: Elapsed time= 1.65 sec
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6677
Sun Nov 17 17:10:19 2013: Cpu = 0.00 sec
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6680
Sun Nov 17 17:10:19 2013: Buffers = 2048
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6682
Sun Nov 17 17:10:19 2013: Reads = 43505
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6698
Sun Nov 17 17:10:19 2013: Writes = 681
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6701
Sun Nov 17 17:10:19 2013: Fetches = 88035
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6704
Sun Nov 17 17:10:19 2013: set echo off;
Sun Nov 17 17:10:19 2013: nfo: receive_packet_noqueue() - 6706

receive_packet_noqueue с натыканным debug-выводом, 122 строки

Код: plaintext

  6646	static void receive_packet_noqueue(rem_port* port, PACKET* packet)
  6647	{
  6648	/**************************************
  6649	 *
  6650	 *	r e c e i v e _ p a c k e t _ n o q u e u e
  6651	 *
  6652	 **************************************
  6653	 *
  6654	 * Functional description
  6655	 *	Receive a packet and check for a network
  6656	 *	error on the receive.
  6657	 *	Note: SOME of the network lower level protocols
  6658	 *	will set up a status vector when errors
  6659	 *	occur, but other ones won't.
  6660	 *	So this routine sets up an error result
  6661	 *	for the vector prior to going into the
  6662	 *	network layer.  Note that we can't
  6663	 *	RESET the status vector as one thing
  6664	 *	that can be received is a new status vector
  6665	 *
  6666	 *	See also cousin routine: send_packet, send_partial_packet
  6667	 *
  6668	 **************************************/
  6669	
  6670		// Receive responses for all deferred packets that were already sent
  6671	        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - intro, %d\n", __LINE__)); // 17.11.2013
  6672		Rdb* rdb = port->port_context;
  6673	        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6674	
  6675		if (port->port_deferred_packets)
  6676		{
  6677	                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6678			while (port->port_deferred_packets->getCount())
  6679			{
  6680	                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6681				rem_que_packet* const p = port->port_deferred_packets->begin();
  6682	                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6683				if (!p->sent)
  6684					break;
  6685	
  6686				OBJCT stmt_id = 0;
  6687				bool bCheckResponse = false, bFreeStmt = false;
  6688	
  6689				if (p->packet.p_operation == op_execute)
  6690				{
  6691	                                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6692					stmt_id = p->packet.p_sqldata.p_sqldata_statement;
  6693					bCheckResponse = true;
  6694	                                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6695				}
  6696				else if (p->packet.p_operation == op_free_statement)
  6697				{
  6698	                                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6699					stmt_id = p->packet.p_sqlfree.p_sqlfree_statement;
  6700					bFreeStmt = (p->packet.p_sqlfree.p_sqlfree_option == DSQL_drop);
  6701	                                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6702				}
  6703	
  6704	                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6705				receive_packet_with_callback(port, &p->packet);
  6706	                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6707	
  6708				Rsr* statement = NULL;
  6709				if (bCheckResponse || bFreeStmt)
  6710				{
  6711	                                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6712					statement = port->port_objects[stmt_id];
  6713	                                HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6714				}
  6715	
  6716				if (bCheckResponse)
  6717				{
  6718					bool bAssign = true;
  6719					try
  6720					{
  6721						LocalStatus status;
  6722	                                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6723						REMOTE_check_response(&status, rdb, &p->packet);
  6724	                                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6725						statement->saveException(status.get(), false);
  6726	                                        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6727					}
  6728					catch (const Exception& ex)
  6729					{
  6730						// save error within the corresponding statement
  6731					        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6732						statement->saveException(ex, false);
  6733						bAssign = false;
  6734					        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6735					}
  6736	
  6737					if (bAssign)
  6738					{
  6739						// assign statement to transaction
  6740					        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6741						const OBJCT tran_id = p->packet.p_sqldata.p_sqldata_transaction;
  6742						Rtr* transaction = port->port_objects[tran_id];
  6743						statement->rsr_rtr = transaction;
  6744					        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6745					}
  6746				}
  6747	
  6748				if (bFreeStmt && p->packet.p_resp.p_resp_object == INVALID_OBJECT)
  6749				{
  6750				        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6751					release_sql_request(statement);
  6752				        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6753				}
  6754	
  6755				// free only part of packet we worked with
  6756			        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6757				REMOTE_free_packet(port, &p->packet, true);
  6758			        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6759				port->port_deferred_packets->remove(p);
  6760			        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6761			}
  6762		}
  6763	        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - %d\n", __LINE__)); // 17.11.2013
  6764	        receive_packet_with_callback(port, packet);
  6765	        HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_noqueue() - bye, %d\n", __LINE__)); // 17.11.2013
  6766	}

Ну при вводе quit тоже откровение вылезло: оказывается, там будет аж четыре вызова receive_packet_with_callback():

isql output

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.
9.

SQL> quit;
nfo: receive_packet_with_callback() - intro, 6606
nfo: receive_packet_with_callback() - bye-1, 6649
nfo: receive_packet_with_callback() - intro, 6606
nfo: receive_packet_with_callback() - bye-1, 6649
nfo: receive_packet_with_callback() - intro, 6606
nfo: receive_packet_with_callback() - bye-1, 6649
nfo: receive_packet_with_callback() - intro, 6606
nfo: receive_packet_with_callback() - bye-1, 6649

Зачем так долго "прощаться" ?

receive_packet_with_callback с натыканным debug-выводом, 66 строк

Код: plaintext

  6589	static void receive_packet_with_callback(rem_port* port, PACKET* packet)
  6590	{
  6591	/**************************************
  6592	 *
  6593	 *	r e c e i v e _ p a c k e t _ w i t h _ c a l l b a c k
  6594	 *
  6595	 **************************************
  6596	 *
  6597	 * Functional description
  6598	 *	If received packet is request from callback info from user,
  6599	 *	send requested info (or no data if callback is not set) and
  6600	 *	wait for next packet.
  6601	 *
  6602	 **************************************/
  6603	
  6604		for (;;)
  6605		{
  6606			HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - intro, %d\n", __LINE__)); // 17.11.2013
  6607			if (!port->receive(packet))
  6608			{
  6609				HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6610				Arg::Gds(isc_net_read_err).raise();
  6611				HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6612			}
  6613	
  6614			switch (packet->p_operation)
  6615			{
  6616			case op_crypt_key_callback:
  6617				{
  6618					P_CRYPT_CALLBACK* cc = &packet->p_cc;
  6619					UCharBuffer buf;
  6620	
  6621					if (port->port_client_crypt_callback)
  6622					{
  6623						if (cc->p_cc_reply <= 0)
  6624						{
  6625							cc->p_cc_reply = 1;
  6626						}
  6627						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6628						UCHAR* reply = buf.getBuffer(cc->p_cc_reply);
  6629						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6630						unsigned l = port->port_client_crypt_callback->callback(cc->p_cc_data.cstr_length,
  6631							cc->p_cc_data.cstr_address, cc->p_cc_reply, reply);
  6632						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6633						cc->p_cc_data.cstr_length = l;
  6634						cc->p_cc_data.cstr_address = reply;
  6635					}
  6636					else
  6637					{
  6638						HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6639						cc->p_cc_data.cstr_length = 0;
  6640					}
  6641					cc->p_cc_data.cstr_allocated = 0;
  6642	
  6643					HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6644					port->send(packet);
  6645					HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - %d\n", __LINE__)); // 17.11.2013
  6646				}
  6647				break;
  6648			default:
  6649				HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - bye-1, %d\n", __LINE__)); // 17.11.2013
  6650				return;
  6651			}
  6652		}
  6653		HANDSHAKE_DEBUG(fprintf(stderr, "nfo: receive_packet_with_callback() - bye, %d\n", __LINE__)); // 17.11.2013

...

Рейтинг:

0 / 0

18.11.2013, 07:24:16

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468132

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

ТаблоидЭто значит, что строки между "1+". . ."1-" - это ПОЛНЫЙ перечень действий сервера в ответ на просьбу установить коннект.
ничего подобного

ТаблоидТогда долгий коннект должен был бы возникать и для любой другой базы на этом хосте, если в этот момент времени идёт молотьба с "основной" тестовой базейкой
с чего ты это взял?

...

Рейтинг:

0 / 0

18.11.2013, 08:50:29

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468155

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

dimitrТаблоидЭто значит, что строки между "1+". . ."1-" - это ПОЛНЫЙ перечень действий сервера в ответ на просьбу установить коннект.ничего подобногоЕсли какие-то действия в "хвосте" не показываются, то... почему так было сделано ?

dimitrТаблоидТогда долгий коннект должен был бы возникать и для любой другой базы на этом хосте, если в этот момент времени идёт молотьба с "основной" тестовой базейкойс чего ты это взял?Со слов:dimitrя в своих тестах долгие коннекты искал (и находил) именно внутри ядра мну померещилось, что слова "внутри ядра" как раз и означают: внутри процесса (-ов) ФБ, которые *не* связаны ни с какой конкретной базой, а заняты чем-то "более важным".
Если это не так, то поясни, плз: ЧТО ТАКОЕ "ЯДРО" в Firebird?

...

Рейтинг:

0 / 0

18.11.2013, 09:23:16

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468168

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

ТаблоидЕсли какие-то действия в "хвосте" не показываются, то... почему так было сделано ?
возможно, оно Алексу не было нужно. Кроме того, это отладочная инфа сугубо авторизации, она не обязана в себя включать собственно коннект к базе.

ТаблоидЕсли это не так, то поясни, плз: ЧТО ТАКОЕ "ЯДРО" в Firebird?
libEngine12.so. В ней нет ни авторизации, ни сетевого протокола, только работа с базой.

...

Рейтинг:

0 / 0

18.11.2013, 09:40:50

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468180

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

dimitrТаблоидЕсли какие-то действия в "хвосте" не показываются, то... почему так было сделано ?возможно, оно Алексу не было нужно. Кроме того, это отладочная инфа сугубо авторизации, она не обязана в себя включать собственно коннект к базе.OK, я буду тогда его трясти на эту тему :-)
dimitrТаблоидЕсли это не так, то поясни, плз: ЧТО ТАКОЕ "ЯДРО" в Firebird?
libEngine12.so. В ней нет ни авторизации, ни сетевого протокола , только работа с базой.Если тормоза внутри libEngine12.so, но в ней нет сетевого протокола, то... почему клинит именно вызов port->receive(packet) ?
Хост при этом точно имеет возможность откликнуться (это показывает и вывод top, и мгновенный коннект к не нагруженной базе).

...

Рейтинг:

0 / 0

18.11.2013, 09:52:18

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468189

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

Таблоидпочему клинит именно вызов port->receive(packet)
потому что она ждет результат установления коннекта ядром

...

Рейтинг:

0 / 0

18.11.2013, 10:03:44

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468415

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

dimitrона ждет результат установления коннекта ядромНу-с, тогда идём дальше. В каком файлике этот код, который "устанавливает коннект ядром", дабы натолкать в него дебаг-вывод и докопаться наконец до истинного затыка ?

...

Рейтинг:

0 / 0

18.11.2013, 12:40:13

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468433

dimitr

Участник

Откуда: PNZ

Сообщения: 7 059

Рейтинг: 0 / 0

Таблоид,

ты это уже делал в прошлом году, ничего полезного это не принесло. Оставь уже эту тему в покое, займись другими вещами.

...

Рейтинг:

0 / 0

18.11.2013, 12:48:08

| Ответить | Цитировать | Написать

И снова о скорости установки коннектов к Firebird при средней и сильной нагрузке

#38468444

Таблоид

Участник

Сообщения: 9 702

Рейтинг: 0 / 0

dimitr,

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

...

Рейтинг:

0 / 0

18.11.2013, 12:54:43

| Ответить | Цитировать | Написать

33 сообщений из 33, показаны все 2 страниц

все

Читали тему (0):

Читали форум (0):

Пользователи онлайн (0):

start [/forum/topic.php?all=1&fid=40&tid=1564133]:	0ms
get settings:	7ms
get forum list:	10ms
check forum access:	2ms
check topic access:	2ms
track hit:	187ms
get topic data:	7ms
get forum data:	2ms
get page messages:	41ms
get tp. blocked users:	1ms
others:	198ms

total:	457ms

	Необходимые cookie
	Cookie для сбора статистики
	Cookie для маркетинга и рекламы