Вести с полей посттестирования v5
Решил прогнать на кодовой базе v5 модульные тесты встроенного клиента к Firebird. В качестве жертв были выбраны FB3.0.4 и FB2.5.6.
100 лет уже эти тесты не запускал — ограничивался основными тестами. Они тоже неплохо так разные варианты перебирают.
В процессе перезапуска тестов на FB2.5.6 (дорабатывал их устаревший код) нарвался на тупняк сервера со списками запросов. Ну, думаю, сейчас тройку замучаю и если на ней тест «RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts» тоже будет тупить — держите меня семеро.
Тесты прогоняются четыре раза ([debug,release]x[32bit,64bit]). В четыре потока. Сам сервер 64битный (релизный код, superserver).
Смотрю четвертый (последний) прогон:
[THR:028840] [15.02.2019 09:18:23] *********************************************** [THR:028840] [15.02.2019 09:18:23] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [THR:028840] [15.02.2019 09:18:23] * [THR:028840] [15.02.2019 09:18:23] [test] Hello from test! [THR:028840] [15.02.2019 09:18:23] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:028840] [15.02.2019 09:18:23] [test] RemoteFB__Connector::StartTransaction ...OK [THR:028840] [15.02.2019 09:18:23] [test] Allocate statements ... [THR:028840] [15.02.2019 09:18:43] [test] OK. We got the error. [THR:028840] [15.02.2019 09:18:43] [test] 1. [Firebird] too many open handles to database [THR:028840] [15.02.2019 09:18:43] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса. [THR:028840] [15.02.2019 09:18:43] [test] nMaxStatements: 64999 [THR:028840] [15.02.2019 09:18:43] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:028840] [15.02.2019 09:18:43] [test] RemoteFB__Connector::StartTransaction ...OK [THR:028840] [15.02.2019 09:18:43] [test] -------------------------------- pass: 1 [THR:028840] [15.02.2019 09:18:43] [test] Allocate statements ... [THR:028840] [15.02.2019 09:18:43] [test] ---- [THR:028840] [15.02.2019 09:19:04] [test] Drop statements ... [THR:028840] [15.02.2019 09:19:04] [test] -------------------------------- pass: 2 [THR:028840] [15.02.2019 09:19:04] [test] Allocate statements ... [THR:028840] [15.02.2019 09:19:47] [test] ---- [THR:028840] [15.02.2019 09:20:08] [test] Drop statements ... [THR:028840] [15.02.2019 09:20:08] [test] -------------------------------- pass: 3 [THR:028840] [15.02.2019 09:20:08] [test] Allocate statements ... [THR:028840] [15.02.2019 09:20:54] [test] ---- [THR:028840] [15.02.2019 09:21:13] [test] Drop statements ... [THR:028840] [15.02.2019 09:21:13] [test] RemoteFB__Connector::Commit ...OK [THR:028840] [15.02.2019 09:21:18] [test] RemoteFB__Connector::DetachDatabase ...OK [THR:028840] [15.02.2019 09:21:18] * [THR:028840] [15.02.2019 09:21:18] * REAL TIME:1753422293 [00:02:55.3422293] [THR:028840] [15.02.2019 09:21:18] * USER TIME:103593750 [00:00:10.3593750] [THR:028840] [15.02.2019 09:21:18] * KERNEL TIME:54531250 [00:00:05.4531250] [THR:028840] [15.02.2019 09:21:18] * TOTAL TIME:158125000 [00:00:15.8125000] [THR:028840] [15.02.2019 09:21:18] * [THR:028840] [15.02.2019 09:21:18] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [THR:028840] [15.02.2019 09:21:18]
«Ух ты, вот это скорость!» (с) Шматрица.
Третий прогон:
[THR:017468] [15.02.2019 07:22:25] *********************************************** [THR:017468] [15.02.2019 07:22:25] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [THR:017468] [15.02.2019 07:22:25] * [THR:017468] [15.02.2019 07:22:25] [test] Hello from test! [THR:017468] [15.02.2019 07:22:25] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:017468] [15.02.2019 07:22:25] [test] RemoteFB__Connector::StartTransaction ...OK [THR:017468] [15.02.2019 07:22:25] [test] Allocate statements ... [THR:017468] [15.02.2019 07:22:48] [test] OK. We got the error. [THR:017468] [15.02.2019 07:22:48] [test] 1. [Firebird] too many open handles to database [THR:017468] [15.02.2019 07:22:48] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса. [THR:017468] [15.02.2019 07:22:48] [test] nMaxStatements: 64999 [THR:017468] [15.02.2019 07:22:49] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:017468] [15.02.2019 07:22:49] [test] RemoteFB__Connector::StartTransaction ...OK [THR:017468] [15.02.2019 07:22:49] [test] -------------------------------- pass: 1 [THR:017468] [15.02.2019 07:22:49] [test] Allocate statements ... [THR:017468] [15.02.2019 07:22:49] [test] ---- [THR:017468] [15.02.2019 07:23:12] [test] Drop statements ... [THR:017468] [15.02.2019 07:23:12] [test] -------------------------------- pass: 2 [THR:017468] [15.02.2019 07:23:12] [test] Allocate statements ... [THR:017468] [15.02.2019 07:23:45] [test] ---- [THR:017468] [15.02.2019 07:24:09] [test] Drop statements ... [THR:017468] [15.02.2019 07:24:10] [test] -------------------------------- pass: 3 [THR:017468] [15.02.2019 07:24:10] [test] Allocate statements ... [THR:017468] [15.02.2019 07:24:45] [test] ---- [THR:017468] [15.02.2019 07:25:09] [test] Drop statements ... [THR:017468] [15.02.2019 07:25:09] [test] RemoteFB__Connector::Commit ...OK [THR:017468] [15.02.2019 07:25:14] [test] RemoteFB__Connector::DetachDatabase ...OK [THR:017468] [15.02.2019 07:25:14] * [THR:017468] [15.02.2019 07:25:14] * REAL TIME:1693444756 [00:02:49.3444756] [THR:017468] [15.02.2019 07:25:14] * USER TIME:337656250 [00:00:33.7656250] [THR:017468] [15.02.2019 07:25:14] * KERNEL TIME:58906250 [00:00:05.8906250] [THR:017468] [15.02.2019 07:25:14] * TOTAL TIME:396562500 [00:00:39.6562500] [THR:017468] [15.02.2019 07:25:14] * [THR:017468] [15.02.2019 07:25:14] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
Так, так…
Первый прогон (руки крюки жеж):
[THR:007156] [15.02.2019 04:12:50] *********************************************** [THR:007156] [15.02.2019 04:12:50] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [THR:007156] [15.02.2019 04:12:50] * [THR:007156] [15.02.2019 04:12:50] [test] Hello from test! [THR:007156] [15.02.2019 04:12:51] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:007156] [15.02.2019 04:12:51] [test] RemoteFB__Connector::StartTransaction ...OK [THR:007156] [15.02.2019 04:12:51] [test] Allocate statements ... [THR:007156] [15.02.2019 04:13:33] [test] OK. We got the error. [THR:007156] [15.02.2019 04:13:33] [test] 1. [Firebird] too many open handles to database [THR:007156] [15.02.2019 04:13:33] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса. [THR:007156] [15.02.2019 04:13:33] [test] nMaxStatements: 64999 [THR:007156] [15.02.2019 04:13:34] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:007156] [15.02.2019 04:13:34] [test] RemoteFB__Connector::StartTransaction ...OK [THR:007156] [15.02.2019 04:13:34] [test] -------------------------------- pass: 1 [THR:007156] [15.02.2019 04:13:34] [test] Allocate statements ... [THR:007156] [15.02.2019 04:13:34] [test] ---- [THR:007156] [15.02.2019 04:14:07] [test] Drop statements ... [THR:007156] [15.02.2019 04:14:08] [test] -------------------------------- pass: 2 [THR:007156] [15.02.2019 04:14:08] [test] Allocate statements ... [THR:007156] [15.02.2019 04:16:02] [test] ---- [THR:007156] [15.02.2019 04:16:27] [test] Drop statements ... [THR:007156] [15.02.2019 04:16:28] [test] -------------------------------- pass: 3 [THR:007156] [15.02.2019 04:16:28] [test] Allocate statements ... [THR:007156] [15.02.2019 04:18:20] [test] ---- [THR:007156] [15.02.2019 04:18:45] [test] Drop statements ... [THR:007156] [15.02.2019 04:18:45] [test] RemoteFB__Connector::Commit ...OK [THR:007156] [15.02.2019 04:18:50] [test] RemoteFB__Connector::DetachDatabase ...OK [THR:007156] [15.02.2019 04:18:50] * [THR:007156] [15.02.2019 04:18:50] * REAL TIME:3603889572 [00:06:00.3889572] [THR:007156] [15.02.2019 04:18:50] * USER TIME:302031250 [00:00:30.2031250] [THR:007156] [15.02.2019 04:18:50] * KERNEL TIME:58906250 [00:00:05.8906250] [THR:007156] [15.02.2019 04:18:50] * TOTAL TIME:360937500 [00:00:36.0937500] [THR:007156] [15.02.2019 04:18:50] * [THR:007156] [15.02.2019 04:18:50] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
Нет, я так не играю. Неужели починили?
Второй прогон:
[THR:001584] [15.02.2019 06:24:14] *********************************************** [THR:001584] [15.02.2019 06:24:14] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [THR:001584] [15.02.2019 06:24:14] * [THR:001584] [15.02.2019 06:24:14] [test] Hello from test! [THR:001584] [15.02.2019 06:24:14] [test] RemoteFB__Connector::ConnectToDatabase ...OK [THR:001584] [15.02.2019 06:24:14] [test] RemoteFB__Connector::StartTransaction ...OK [THR:001584] [15.02.2019 06:24:14] [test] Allocate statements ... [THR:001584] [15.02.2019 06:24:34] [test] OK. We got the error. [THR:001584] [15.02.2019 06:24:34] [test] 1. [Firebird] too many open handles to database [THR:001584] [15.02.2019 06:24:34] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса. [THR:001584] [15.02.2019 06:24:34] [test] nMaxStatements: 64999 [THR:001584] [15.02.2019 06:24:34] [test] RemoteFB__Connector::ConnectToDatabase ... FAILED [THR:001584] [15.02.2019 06:24:34] ERROR: [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [LCPI.IBProvider.5] [winsock] Сбой чтения данных из порта подключения. Ошибка WinSock: 10054. [THR:001584] [15.02.2019 06:24:34] * [THR:001584] [15.02.2019 06:24:34] * REAL TIME:201587949 [00:00:20.1587949] [THR:001584] [15.02.2019 06:24:34] * USER TIME:26406250 [00:00:02.6406250] [THR:001584] [15.02.2019 06:24:34] * KERNEL TIME:19843750 [00:00:01.9843750] [THR:001584] [15.02.2019 06:24:34] * TOTAL TIME:46250000 [00:00:04.6250000] [THR:001584] [15.02.2019 06:24:34] * [THR:001584] [15.02.2019 06:24:34] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
Сервер таки навернулся и перезапустился:
Даже немного грустно стало, он достаточно долго прожил:
Состояние на 12 февраля 2019 года.
Дескрипторы текут. Думал — сейчас через неделю еще один screenshot сделаю. Не судьба.
В логе сервера по поводу этого краша — пусто.
В журнале Windows:
Служба Firebird Server — DefaultInstance была неожиданно завершена. Это произошло 1 раз(а). Следующее корректирующее действие будет предпринято через 0 мсек: Перезапуск службы.
В других потоках этого прогона пишут:
[THR:007372] [15.02.2019 06:24:34] *********************************************** [THR:007372] [15.02.2019 06:24:34] * START TEST [RemoteFB.WORK.019.StmtExecute.v1.ptype__batch_send.S008.insert.with_param3] [THR:007372] [15.02.2019 06:24:34] * [THR:007372] [15.02.2019 06:24:34] [test] Hello from test! [THR:007372] [15.02.2019 06:24:34] [test] RemoteFB__Connector::ConnectToDatabase ... FAILED [THR:007372] [15.02.2019 06:24:34] ERROR: [RemoteFB.WORK.019.StmtExecute.v1.ptype__batch_send.S008.insert.with_param3] [LCPI.IBProvider.5] [winsock] Сбой чтения данных из порта подключения. Ошибка WinSock: 10054.
Параллельно на сервере работало стандартное нагрузочное тестирование. На другой базе. Там пишут следующее:
[THR:035180] [15.02.2019 06:21:08] ***********************************************
[THR:035180] [15.02.2019 06:21:08] * START TEST [rowset.large_row.rw_update__asynch_fetch.cache_1024]
[THR:035180] [15.02.2019 06:21:08] *
[THR:035180] [15.02.2019 06:21:08] * PREPARE
[THR:035180] [15.02.2019 06:21:08] * RUN
[THR:035180] [15.02.2019 06:21:08] [test] Test row ids: [1...65537)
[THR:035180] [15.02.2019 06:21:08] [test] create pooled data source...
[THR:035180] [15.02.2019 06:21:08] [test] connect to database ...OK
[THR:035180] [15.02.2019 06:21:08] [test] Session Create ...
[THR:035180] [15.02.2019 06:21:08] [test] START TRANSACTION ...
[THR:035180] [15.02.2019 06:21:08] [test] ------------- [Read and check row data]
[THR:035180] [15.02.2019 06:21:08] [test] RowCacheSize: 1024
[THR:035180] [15.02.2019 06:21:08] [test] Create command ...
[THR:035180] [15.02.2019 06:21:08] [test] "IRowsetUpdate"=[TRUE [-1]] ...OK
[THR:035180] [15.02.2019 06:21:08] [test] "IRowsetChange"=[TRUE [-1]] ...OK
[THR:035180] [15.02.2019 06:21:08] [test] Set Command Prop [201][{C8B522BE-5CF3-11CE-ADE5-00AA0044773D}]: 8L
[THR:035180] [15.02.2019 06:21:08] [test] OK. We got the correct result status of call: [S_OK][DBPROPSTATUS_OK]
[THR:035180] [15.02.2019 06:21:08] [test] Prepare Command:
"select test_id,large_text from TEST_LARGE_ROW
where test_id>=? and test_id<?
order by test_id"
[THR:035180] [15.02.2019 06:21:08] [test] EXECUTE COMMAND (or=true,rpi=true)
[THR:035180] [15.02.2019 06:21:08] [test] [0][in][]:I8[S_OK][1]
[THR:035180] [15.02.2019 06:21:08] [test] [1][in][]:I8[S_OK][65537]
[THR:035180] [15.02.2019 06:21:08] [test]
[THR:035180] [15.02.2019 06:21:08] [test] pass: 1
[THR:035180] [15.02.2019 06:21:08] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:21:56] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:21:56] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:21:56] [test]
[THR:035180] [15.02.2019 06:21:56] [test] pass: 2
[THR:035180] [15.02.2019 06:21:56] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:22:19] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:22:19] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:22:19] [test]
[THR:035180] [15.02.2019 06:22:19] [test] pass: 3
[THR:035180] [15.02.2019 06:22:19] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:22:40] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:22:40] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:22:40] [test]
[THR:035180] [15.02.2019 06:22:40] [test] pass: 4
[THR:035180] [15.02.2019 06:22:40] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:23:03] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:23:03] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:23:03] [test]
[THR:035180] [15.02.2019 06:23:03] [test] pass: 5
[THR:035180] [15.02.2019 06:23:03] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:23:35] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:23:35] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:23:35] [test]
[THR:035180] [15.02.2019 06:23:35] [test] pass: 6
[THR:035180] [15.02.2019 06:23:35] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:23:59] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:23:59] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:23:59] [test]
[THR:035180] [15.02.2019 06:23:59] [test] pass: 7
[THR:035180] [15.02.2019 06:23:59] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:24:25] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:24:25] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:24:25] [test]
[THR:035180] [15.02.2019 06:24:25] [test] pass: 8
[THR:035180] [15.02.2019 06:24:25] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:24:49] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:24:49] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:24:49] [test]
[THR:035180] [15.02.2019 06:24:49] [test] pass: 9
[THR:035180] [15.02.2019 06:24:49] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:25:22] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:25:22] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:25:22] [test]
[THR:035180] [15.02.2019 06:25:22] [test] pass: 10
[THR:035180] [15.02.2019 06:25:22] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:25:51] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:25:51] [test] COMMIT TRANSACTION [RETAINING=false]...
[THR:035180] [15.02.2019 06:25:51] ERROR: [rowset.large_row.rw_update__asynch_fetch.cache_1024] Commit transaction
1. [LCPI.IBProvider.5]: [winsock] Сбой записи данных в порт подключения. Ошибка WinSock: 10054.
2. [LCPI.IBProvider.5]: Ошибка подтверждения транзакции. Транзакция будет отменена.
3. [LCPI.IBProvider.5]: [Подсистема: remote_fb] Запись в порт невозможна. Предыдущая операция записи завершилась с ошибками.
4. [LCPI.IBProvider.5]: Ошибка отката транзакции.
Неопознанная ошибка
COM Error Code: E_FAIL
[THR:035180] [15.02.2019 06:25:51] *
[THR:035180] [15.02.2019 06:25:51] * REAL TIME: 2836405955 [00:04:43.6405955]
[THR:035180] [15.02.2019 06:25:51] * USER TIME: 1949375000 [00:03:14.9375000]
[THR:035180] [15.02.2019 06:25:51] * KERNEL TIME: 94218750 [00:00:09.4218750]
[THR:035180] [15.02.2019 06:25:51] * TOTAL TIME: 2043593750 [00:03:24.3593750]
[THR:035180] [15.02.2019 06:25:51] *
[THR:035180] [15.02.2019 06:25:51] * ERROR COUNT: 1
[THR:035180] [15.02.2019 06:25:51] * WARNING COUNT: 0
[THR:035180] [15.02.2019 06:25:51] *
[THR:035180] [15.02.2019 06:25:51] * STOP TEST [rowset.large_row.rw_update__asynch_fetch.cache_1024]
[THR:035180] [15.02.2019 06:25:51]
[THR:044488] [15.02.2019 06:20:00] ***********************************************
[THR:044488] [15.02.2019 06:20:00] * START TEST [rowset.large_row.rw_update__asynch_fetch.cache_128]
[THR:044488] [15.02.2019 06:20:00] *
[THR:044488] [15.02.2019 06:20:00] * PREPARE
[THR:044488] [15.02.2019 06:20:00] * RUN
[THR:044488] [15.02.2019 06:20:00] [test] Test row ids: [1...65537)
[THR:044488] [15.02.2019 06:20:00] [test] create pooled data source...
[THR:044488] [15.02.2019 06:20:00] [test] connect to database ...OK
[THR:044488] [15.02.2019 06:20:00] [test] Session Create ...
[THR:044488] [15.02.2019 06:20:00] [test] START TRANSACTION ...
[THR:044488] [15.02.2019 06:20:00] [test] ------------- [Read and check row data]
[THR:044488] [15.02.2019 06:20:00] [test] RowCacheSize: 128
[THR:044488] [15.02.2019 06:20:00] [test] Create command ...
[THR:044488] [15.02.2019 06:20:00] [test] "IRowsetUpdate"=[TRUE [-1]] ...OK
[THR:044488] [15.02.2019 06:20:00] [test] "IRowsetChange"=[TRUE [-1]] ...OK
[THR:044488] [15.02.2019 06:20:00] [test] Set Command Prop [201][{C8B522BE-5CF3-11CE-ADE5-00AA0044773D}]: 8L
[THR:044488] [15.02.2019 06:20:00] [test] OK. We got the correct result status of call: [S_OK][DBPROPSTATUS_OK]
[THR:044488] [15.02.2019 06:20:00] [test] Prepare Command:
"select test_id,large_text from TEST_LARGE_ROW
where test_id>=? and test_id<?
order by test_id"
[THR:044488] [15.02.2019 06:20:00] [test] EXECUTE COMMAND (or=true,rpi=true)
[THR:044488] [15.02.2019 06:20:00] [test] [0][in][]:I8[S_OK][1]
[THR:044488] [15.02.2019 06:20:00] [test] [1][in][]:I8[S_OK][65537]
[THR:044488] [15.02.2019 06:20:00] [test]
[THR:044488] [15.02.2019 06:20:00] [test] pass: 1
[THR:044488] [15.02.2019 06:20:00] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:20:59] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:20:59] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:20:59] [test]
[THR:044488] [15.02.2019 06:20:59] [test] pass: 2
[THR:044488] [15.02.2019 06:20:59] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:21:24] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:21:24] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:21:24] [test]
[THR:044488] [15.02.2019 06:21:24] [test] pass: 3
[THR:044488] [15.02.2019 06:21:24] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:21:47] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:21:47] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:21:47] [test]
[THR:044488] [15.02.2019 06:21:47] [test] pass: 4
[THR:044488] [15.02.2019 06:21:47] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:22:10] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:22:10] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:22:10] [test]
[THR:044488] [15.02.2019 06:22:10] [test] pass: 5
[THR:044488] [15.02.2019 06:22:10] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:22:31] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:22:31] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:22:31] [test]
[THR:044488] [15.02.2019 06:22:31] [test] pass: 6
[THR:044488] [15.02.2019 06:22:31] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:22:54] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:22:54] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:22:54] [test]
[THR:044488] [15.02.2019 06:22:54] [test] pass: 7
[THR:044488] [15.02.2019 06:22:54] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:23:23] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:23:23] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:23:23] [test]
[THR:044488] [15.02.2019 06:23:23] [test] pass: 8
[THR:044488] [15.02.2019 06:23:23] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:23:49] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:23:49] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:23:49] [test]
[THR:044488] [15.02.2019 06:23:49] [test] pass: 9
[THR:044488] [15.02.2019 06:23:49] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:24:14] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:24:14] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:24:14] [test]
[THR:044488] [15.02.2019 06:24:14] [test] pass: 10
[THR:044488] [15.02.2019 06:24:14] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:24:39] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:24:39] [test] COMMIT TRANSACTION [RETAINING=false]...
[THR:044488] [15.02.2019 06:24:39] ERROR: [rowset.large_row.rw_update__asynch_fetch.cache_128] Commit transaction
1. [LCPI.IBProvider.5]: [winsock] Сбой записи данных в порт подключения. Ошибка WinSock: 10054.
2. [LCPI.IBProvider.5]: Ошибка подтверждения транзакции. Транзакция будет отменена.
3. [LCPI.IBProvider.5]: [Подсистема: remote_fb] Запись в порт невозможна. Предыдущая операция записи завершилась с ошибками.
4. [LCPI.IBProvider.5]: Ошибка отката транзакции.
Неопознанная ошибка
COM Error Code: E_FAIL
[THR:044488] [15.02.2019 06:24:39] *
[THR:044488] [15.02.2019 06:24:39] * REAL TIME: 2795972264 [00:04:39.5972264]
[THR:044488] [15.02.2019 06:24:39] * USER TIME: 1882656250 [00:03:08.2656250]
[THR:044488] [15.02.2019 06:24:39] * KERNEL TIME: 90312500 [00:00:09.0312500]
[THR:044488] [15.02.2019 06:24:39] * TOTAL TIME: 1972968750 [00:03:17.2968750]
[THR:044488] [15.02.2019 06:24:39] *
[THR:044488] [15.02.2019 06:24:39] * ERROR COUNT: 1
[THR:044488] [15.02.2019 06:24:39] * WARNING COUNT: 0
[THR:044488] [15.02.2019 06:24:39] *
[THR:044488] [15.02.2019 06:24:39] * STOP TEST [rowset.large_row.rw_update__asynch_fetch.cache_128]
[THR:044488] [15.02.2019 06:24:39]
В остальных двух потоках ошибки в том же духе.
Сижу и думаю, это у меня уже профессиональное чутьё или инстинкт самосохранения сработал — не запускать эти тесты в процессе финального тестирования v5. Я бы кучу времени потерял.