Вести с полей

С 15 июня было запущено большое тестирование. Все тесты основой тестовой систему (их там за 8 млн).

Сразу на двух базах — с первым и третьим диалектами. То есть работают два тестовых процесса. В каждом по 4 потока.

Эксперимент не является «чистым», поскольку на этом сервере попутно много раз запускались другие многодневные тесты. Разумеется на других файлах баз данных.

В качестве подопытных кроликов, используются IBProvider 3.50.1.28665 x64 и Firebird 3.0.4.32985 x64 SS.

Каждый час отрабатывает сборка мусора для каждой из баз данных.

Пока обнаружена только одна новая «проблема». Достаточно забавная. С базой данных первого диалекта.

[THR:032792] [13.07.2018 22:41:20] [test] insert records ...
[THR:032792] [13.07.2018 22:41:21] ERROR: [test] RecNum:769
[THR:032792] [13.07.2018 22:41:21] ERROR: [blob.002.cmd.disable_defer_data.ansi.TBL_CS__NONE.COL_BLOB.param_adLongVarWChar.bind__iunknown_byref.small.len_2.chars_CP943C.ins_UTF8.sel_CP943C.block_1] Execution of command
1. [LCPI.IBProvider.3]: Ошибка формирования ib-значения входящего параметра. Позиция 1.

Конвертирование из [DBTYPE_I8] в [DBTYPE_I4].

COM Error Code: DB_E_DATAOVERFLOW

Произошло переполнение генератора, а тесты этот момент не прорюхали. Сейчас значение проблемного генератора равно -407 014 391.

В остальном все нормально.

Уже проехало по 7 млн тестов. Базы не пухнут.

Текущее состояние сервера выглядит так:

Оставайтесь на связи и вы узнаете финал этого эпического тестирования 🙂

Dmitry Kovalenko on 3 августа, 2018 | Filed Under IBProvider

3 комментария

Dmitry Kovalenko on 5 августа, 2018

Все закончилось достаточно смешным образом.

Я забыл закрыть IBE с открытым подключением к базе данных первого диалекта. Понятное дело — с активной транзакцией.

В результате эта база выжрала место на RAM-диске и кино закончилось.

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

[04.08.2018 23:57:04] [summary] ------------------------------------------- [SUMMARY INFORMATION]
[04.08.2018 23:57:04] [summary] [TESTS]
[04.08.2018 23:57:04] [summary] EXECUTED      : 7032069
[04.08.2018 23:57:04] [summary] SUCCEEDED     : 6967947
[04.08.2018 23:57:04] [summary] FAILED        : 64120 [ 66423 error(s) ]
[04.08.2018 23:57:04] [summary] WITH WARNINGS : 2 [ 2 warning(s) ]
[04.08.2018 23:57:04] [summary] 
[04.08.2018 23:57:04] [summary] - - - - - - - - - - - - - - - - - - - - - -
[04.08.2018 23:57:04] [summary] [TEST TIMES]
[04.08.2018 23:57:04] [summary] REAL          : 172986591084374 [200 day(s)05:10:59.1084374]
[04.08.2018 23:57:04] [summary] USER          : 26438125468750 [30 day(s)14:23:32.5468750]
[04.08.2018 23:57:04] [summary] KERNEL        : 13794666250000 [15 day(s)23:11:06.6250000]
[04.08.2018 23:57:04] [summary] TOTAL         : 40232791718750 [46 day(s)13:34:39.1718750]
[04.08.2018 23:57:05] 
[04.08.2018 23:57:05] [TEST HEAP] Test heap is empty
[04.08.2018 23:57:05] [TEST HEAP] Validate ... OK
[04.08.2018 23:57:05] [TEST HEAP] Destroy ... OK
[04.08.2018 23:57:05] 
[04.08.2018 23:57:05] [summary] ------------------------------------------- [PROCESS INFORMATION]
[04.08.2018 23:57:05] [summary] [VIRTUAL MEMORY]
[04.08.2018 23:57:05] [summary] 
[04.08.2018 23:57:05] [summary] PRIVATE BYTES      : 9092 KB        [8MB 900KB]
[04.08.2018 23:57:05] [summary] PEAK PRIVATE BYTES : 408000 KB      [398MB 448KB]
[04.08.2018 23:57:05] [summary] VIRTUAL SIZE       : 155996 KB      [152MB 348KB]
[04.08.2018 23:57:05] [summary] PAGE FAULT COUNT   : 1590509361
[04.08.2018 23:57:05] [summary] 
[04.08.2018 23:57:05] [summary] - - - - - - - - - - - - - - - - - - - - - -
[04.08.2018 23:57:05] [summary] [HANDLES]
[04.08.2018 23:57:05] [summary] 
[04.08.2018 23:57:05] [summary] HANDLES            : 157
[04.08.2018 23:57:05] [summary] 
[04.08.2018 23:57:05] [summary] - - - - - - - - - - - - - - - - - - - - - -
[04.08.2018 23:57:05] [summary] TOTAL ERRORS  : 66423
[04.08.2018 23:57:05] [summary] TOTAL WARNINGS: 2
[04.08.2018 23:57:05] [summary] FULL PASSES   : 1
[04.08.2018 23:57:05] [summary] GEN TESTS     : 8295127

А вот тестам с базой третьего диалекта не повезло. Журнал Windows говорит следующее:

Имя сбойного приложения: ibp_oledb_test_vc15_x64_Release.exe, версия: 0.0.0.0, метка времени: 0x5b18b591
Имя сбойного модуля: ucrtbase.dll, версия: 10.0.16299.248, метка времени: 0xe71e5dfe
Код исключения: 0xc0000409
Смещение ошибки: 0x000000000006b79e
Идентификатор сбойного процесса: 0x1688
Время запуска сбойного приложения: 0x01d40472b9c4e8a3
Путь сбойного приложения: d:\Users\Dima\Work\TestCode\ActiveX\IBP\oledb_test_clear\target\ibp_oledb_test_vc15_x64_Release.exe
Путь сбойного модуля: C:\WINDOWS\System32\ucrtbase.dll
Идентификатор отчета: 4336f4d4-0a68-448f-afcf-f25063631241
Полное имя сбойного пакета: 
Код приложения, связанного со сбойным пакетом:

И с этим нужно будет еще разбираться.

Сервер пережил произошедшую катастрофу без проблем 🙂

Dmitry Kovalenko on 5 августа, 2018

Выяснил причину падения.

 	ucrtbase.dll!00007ffc55aeb79e()	Unknown
 	ucrtbase.dll!00007ffc55aeae4f()	Unknown
 	VCRUNTIME140.dll!00007ffc51e32388()	Unknown
 	VCRUNTIME140.dll!00007ffc51e31ec2()	Unknown
 	VCRUNTIME140.dll!00007ffc51e3b950()	Unknown
 	ibp_oledb_test_vc15_x64_Release.exe!__GSHandlerCheck_EH(_EXCEPTION_RECORD * ExceptionRecord, void * EstablisherFrame, _CONTEXT * ContextRecord, _DISPATCHER_CONTEXT * DispatcherContext) Line 114	C
 	ntdll.dll!00007ffc58c650bd()	Unknown
 	ntdll.dll!00007ffc58bdd278()	Unknown
 	ntdll.dll!00007ffc58bdb6e3()	Unknown
 	KERNELBASE.dll!00007ffc55b94008()	Unknown
 	VCRUNTIME140.dll!00007ffc51e344f2()	Unknown
 	ibp_oledb_test_vc15_x64_Release.exe!ole_lib::t_ole_error::generate(HRESULT hr, structure::t_basic_const_str_box<char> what_arg, structure::t_basic_const_str_box<char> text) Line 48	C++
 	ibp_oledb_test_vc15_x64_Release.exe!ole_lib::t_ole_error::throw_error(HRESULT hr, structure::t_basic_const_str_box<char> verb) Line 69	C++
>	ibp_oledb_test_vc15_x64_Release.exe!ibp_tso::TTSO_Table_TestModifyRow1::~TTSO_Table_TestModifyRow1() Line 869	C++
 	VCRUNTIME140.dll!00007ffc51e3c1e0()	Unknown

Классика жанра — необработанное исключение в деструкторе одного из классов тестовой системы.

Привет из 2009 года.

1.1          (ramzes   20-May-09): TTSO_Table_TestModifyRow1::~TTSO_Table_TestModifyRow1()
1.1          (ramzes   20-May-09): {
1.1          (ramzes   20-May-09):  assert(m_spCtx);
1.1          (ramzes   20-May-09):  assert(m_spSD);
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  //----------
1.1          (ramzes   20-May-09):  TTSO_Tracer tracer(m_spCtx,L"test_table");
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  //----------
1.1          (ramzes   20-May-09):  tracer<<L"DELETE TEST TABLE TEST_MODIFY_ROW_1..."<<send;
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  //----------
1.1          (ramzes   20-May-09):  t_db_data_source data_source;
1.1          (ramzes   20-May-09):  _TSO_TRACE_OLEDB(data_source,initialize(m_spSD->m_args.get(c_prog_arg_cn_str)->m_value))
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  //----------
1.1          (ramzes   20-May-09):  t_db_session session;
1.1          (ramzes   20-May-09):  _TSO_TRACE_OLEDB(session,create(data_source));
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  //----------
1.1          (ramzes   20-May-09):  const TTSO_DDL_LockToWrite __lock_ddl(m_spSD->m_ddl_lock);
1.1          (ramzes   20-May-09): 
1.12         (Dima     18-Sep-12):  srv::exec_immed(tracer,session,L"SET TRANSACTION WAIT",NULL);
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  wstr_formatter fstmt;
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  //----------
1.1          (ramzes   20-May-09):  srv::exec_immed(tracer,
1.1          (ramzes   20-May-09):                  session,
1.1          (ramzes   20-May-09):                  fstmt(L"DROP TRIGGER %1")<<m_trigger_name<<c_str,
1.1          (ramzes   20-May-09):                  NULL);
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  srv::exec_immed(tracer,
1.1          (ramzes   20-May-09):                  session,
1.1          (ramzes   20-May-09):                  fstmt(L"DROP TABLE %1")<<m_table_name<<c_str,
1.1          (ramzes   20-May-09):                  NULL);
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):   //OLD servers do not support this statement
1.1          (ramzes   20-May-09):  srv::exec_immed_ignore_err
1.1          (ramzes   20-May-09):                 (tracer,
1.1          (ramzes   20-May-09):                  session,
1.1          (ramzes   20-May-09):                  fstmt(L"DROP GENERATOR %1")<<m_gen_name<<c_str,
1.1          (ramzes   20-May-09):                  NULL);
1.1          (ramzes   20-May-09): 
1.1          (ramzes   20-May-09):  srv::session_commit(tracer,session);
1.1          (ramzes   20-May-09): }//~TTSO_Table_TestModifyRow1

Самое интересное, что в 12 году я туда заглядывал. Но не осознал эту мину замедленного действия.

Там рядом таких деструкторов еще достаточно много 🙂

Dmitry Kovalenko on 6 августа, 2018

Не.

Кажись пламенный привет разработчикам Firebird таки можно передать.

Похоже оно тут зациклилось:

IBProvider Developer's Blog