Большое тестирование #3
Всем привет.
Как я тут уже упоминал — 16 октября было запущено третье «большое тестирование» IBProvider-а. Второе было весной текущего года.
«Добежать» до финиша опять не удалось. Однако в этот раз из-за проблем с Firebird. Судя по всему, 16 ноября (то есть через месяц после старта) произошло зацикливание внутри движка.
Так что, если у вас есть какие-то мысли по поводу использования FB в «высоконагруженных» системах, почитайте. Думаю, здесь есть над чем задуматься.
Конфигурация.
- IBProvider 3.16.5.15407 x64
- Firebird 2.5.3.26709 SuperClassic x64. Откомпилирован в VS2010 с полной оптимизацией кода. Модифицировано только ICU.
- OS: Vista x64
- Q6600 / 8GB / выделенный массив 4x1TB WD RE3 в RAID0 на RS2BL040
Тесты работали в 4 потока. Применялся пул подключений. Само подключение к базе было через localhost.
Там где имело смысл, использовалась асинхронная загрузка результирующих множеств.
Состояние базы данных.
Общее число завершившихся тестов: 356649.
Database "d:\database\ibp_test_fb25_d3_2.gdb"
Database header page information:
Flags 0
Checksum 12345
Generation 42732165
Page size 8192
ODS version 11.2
Oldest transaction 42385444
Oldest active 42385445
Oldest snapshot 42385439
Next transaction 42672549
Bumped transaction 1
Sequence number 0
Next attachment ID 59614
Implementation ID 26
Shadow count 0
Page buffers 0
Next header page 0
Database dialect 3
Creation date Oct 16, 2013 15:02:05
Attributes
Variable header data:
*END*
В среднем получается на одно подключение пришлось 715 транзакций.
Файл базы данных «опух» до 1.2TB:
Формально — в базе нет никаких данных. Потому что все тесты, за редким исключением, удаляют свои тестовые записи.
Состояние серверного процесса.
Информация о серверном процессе.
Ресурсы серверного процесса на 3 декабря.
Ресурсы серверного процесса на 16 ноября.
Проблема #1.
Утром 16 ноября 3 тестовых потока вызвали isc_dsql_execute2 для запроса "INSERT INTO TBL_CS__UTF8" и до сих пор ожидают завершения работы этого метода. То есть формально ожидают завершения операции в сервером процессе.
Сначала я предполагал, что они там начали сборку мусора — через таблицу TBL_CS__UTF8 прошло (insert/delete) огромное количество записей.
gstat.exe для этой таблицы выдает такую информацию:
TBL_CS__UTF8 (179)
Primary pointer page: 163201525, Index root page: 644
Average record length: 0.00, total records: 17564021
Average version length: 27.00, total versions: 17563766, max versions: 1
Data pages: 1167361, data page slots: 1167361, average fill: 96%
Fill distribution:
0 - 19% = 0
20 - 39% = 0
40 - 59% = 0
60 - 79% = 3
80 - 99% = 1167358
Index PK_TBL_CHAR__UTF8 (0)
Depth: 4, leaf buckets: 4935566, nodes: 2709048409
Average data length: 4.43, total dup: 0, max dup: 0
Fill distribution:
0 - 19% = 64922
20 - 39% = 1105
40 - 59% = 1423728
60 - 79% = 258569
80 - 99% = 3187242
Однако позже выяснилось, что все три потока нарезают круги в методе extend_relation:
static void extend_relation( thread_db* tdbb, jrd_rel* relation, WIN* window)
{
/**************************************
*
* e x t e n d _ r e l a t i o n
*
**************************************
*
* Functional description
* Extend a relation with a given page. The window points to an
* already allocated, fetched, and marked data page to be inserted
* into the pointer pages for a given relation.
* This routine returns a window on the datapage locked for write
*
**************************************/
SET_TDBB(tdbb);
Database* dbb = tdbb->getDatabase();
CHECK_DBB(dbb);
RelationPages* relPages = relation->getPages(tdbb);
WIN pp_window(relPages->rel_pg_space_id, -1),
new_pp_window(relPages->rel_pg_space_id, -1);
#ifdef VIO_DEBUG
if (debug_flag > DEBUG_WRITES_INFO) {
printf(" extend_relation (relation %d, window)\n", relation->rel_id);
}
#endif
// Release faked page before fetching pointer page to prevent deadlocks. This is only
// a problem for multi-threaded servers using internal latches. The faked page may be
// dirty from its previous incarnation and involved in a precedence relationship. This
// special case may need a more general solution.
CCH_RELEASE(tdbb, window);
/* Search pointer pages for an empty slot.
If we run out of pointer pages, allocate another one. Note that the code below
is not careful in preventing deadlocks when it allocates a new pointer page:
- the last already-existing pointer page is fetched with an exclusive latch,
- allocation of a new pointer page requires the fetching of the PIP page with
an exlusive latch.
This might cause a deadlock. Fortunately, pointer pages don't need to be
allocated often. */
pointer_page* ppage = NULL;
USHORT pp_sequence, slot = 0;
data_page* dpage = NULL;
for (;;)
{
for (pp_sequence = relPages->rel_slot_space;; pp_sequence++)
{
if (!(ppage = get_pointer_page(tdbb, relation, relPages, &pp_window,
pp_sequence, LCK_write)))
{
BUGCHECK(253); // msg 253 pointer page vanished from extend_relation
}
SLONG* slots = ppage->ppg_page;
for (slot = 0; slot < ppage->ppg_count; slot++, slots++)
{
if (*slots == 0) {
break;
}
}
if (slot < ppage->ppg_count) {
break;
}
if ((pp_sequence && ppage->ppg_count < dbb->dbb_dp_per_pp) ||
(ppage->ppg_count < dbb->dbb_dp_per_pp - 1))
{
slot = ppage->ppg_count;
break;
}
if (ppage->ppg_header.pag_flags & ppg_eof)
{
ppage = (pointer_page*) DPM_allocate(tdbb, &new_pp_window);
ppage->ppg_header.pag_type = pag_pointer;
ppage->ppg_header.pag_flags |= ppg_eof;
ppage->ppg_relation = relation->rel_id;
ppage->ppg_sequence = ++pp_sequence;
slot = 0;
CCH_must_write(&new_pp_window);
CCH_RELEASE(tdbb, &new_pp_window);
vcl* vector = relPages->rel_pages =
vcl::newVector(*dbb->dbb_permanent, relPages->rel_pages, pp_sequence + 1);
(*vector)[pp_sequence] = new_pp_window.win_page.getPageNum();
// hvlad: temporary tables don't save their pointer pages in RDB$PAGES
if (relation->rel_id && (relPages->rel_instance_id == 0))
{
DPM_pages(tdbb, relation->rel_id, pag_pointer,
(SLONG) pp_sequence, new_pp_window.win_page.getPageNum());
}
relPages->rel_slot_space = pp_sequence;
ppage = (pointer_page*) pp_window.win_buffer;
CCH_MARK(tdbb, &pp_window);
ppage->ppg_header.pag_flags &= ~ppg_eof;
ppage->ppg_next = new_pp_window.win_page.getPageNum();
--pp_sequence;
}
CCH_RELEASE(tdbb, &pp_window);
}
// We've found a slot. Stick in the pointer to the data page
if (ppage->ppg_page[slot])
{
CCH_RELEASE(tdbb, &pp_window);
CORRUPT(258); // msg 258 page slot not empty
}
// Refetch newly allocated page that was released above.
// To prevent possible deadlocks (since we own already an exlusive latch and we
// are asking for another exclusive latch), time out on the latch after 1 second.
dpage = (data_page*) CCH_FETCH_TIMEOUT(tdbb, window, LCK_write, pag_undefined, -1);
// In the case of a timeout, retry the whole thing.
if (!dpage) {
CCH_RELEASE(tdbb, &pp_window);
}
else
break;
}
CCH_MARK(tdbb, window);
dpage->dpg_sequence = (SLONG) pp_sequence * dbb->dbb_dp_per_pp + slot;
dpage->dpg_relation = relation->rel_id;
dpage->dpg_header.pag_type = pag_data;
relPages->rel_data_space = pp_sequence;
CCH_RELEASE(tdbb, window);
CCH_precedence(tdbb, &pp_window, window->win_page);
CCH_MARK_SYSTEM(tdbb, &pp_window);
ppage->ppg_page[slot] = window->win_page.getPageNum();
ppage->ppg_min_space = MIN(ppage->ppg_min_space, slot);
ppage->ppg_count = MAX(ppage->ppg_count, slot + 1);
UCHAR* bits = (UCHAR *) (ppage->ppg_page + dbb->dbb_dp_per_pp);
bits[slot >> 2] &= ~(1 << ((slot & 3) << 1));
if (relPages->rel_data_pages) {
++relPages->rel_data_pages;
}
*window = pp_window;
CCH_HANDOFF(tdbb, window, ppage->ppg_page[slot], LCK_write, pag_data);
#ifdef VIO_DEBUG
if (debug_flag > DEBUG_WRITES_INFO)
{
printf(" extended_relation (relation %d, window_page %"SLONGFORMAT")\n",
relation->rel_id, window->win_page.getPageNum());
}
#endif
}
То есть цикл с переменной pp_sequence (строки: 2974-3027) крутится «вечно». Убойно, конечно, что в нем отсутствует сторож зацикливания.
Проблема #2.
Четвертому тестовому потоку повезло немного больше. Он проработал до вечера 16 ноября. Предпоследний тест этого потока завершился по ошибке — запрос "delete from TBL_CS__UTF8 where TEST_ID>=? and TEST_ID<=?" вернул RowsAffected равный 110, вместо ожидаемых 255:
Поскольку тест завершился по ошибке, он откатил операцию удаления и записи остались в базе данных.
Выборка из этого диапазона возвращает все 255 записей. Я пробовал разные запросы:
select * from TBL_CS__UTF8 where (1=0) or (TEST_ID>=2718136087 and TEST_ID<=2718136341); select * from TBL_CS__UTF8 where (TEST_ID>=2718136087 and TEST_ID<=2718136341); select count(*) from TBL_CS__UTF8 where (1=0) or (TEST_ID>=2718136087 and TEST_ID<=2718136341); select count(*) from TBL_CS__UTF8 where (TEST_ID>=2718136087 and TEST_ID<=2718136341);
Все работает как ожидается.
Повторный delete, кстати, тоже возвращает правильный RowsAffected: 255.
Но эти эксперименты я делал через новые подключения (с выключенной сборкой мусора). И возможно глюк был связан именно с многократно использованным подключением.
Следующий (последний) запущенный тест четвертого потока ушел (вслед за своими тремя братьями) на сервер и больше оттуда не возвращался. Единственно отличие — он зациклился в другом месте:
static rhd* locate_space(thread_db* tdbb,
record_param* rpb,
SSHORT size, PageStack& stack, Record* record, USHORT type)
{
/**************************************
*
* l o c a t e _ s p a c e
*
**************************************
*
* Functional description
* Find space in a relation for a record. Find a likely data page
* and call find_space to see if there really is space there. If
* we can't find any space, extend the relation.
*
**************************************/
SET_TDBB(tdbb);
Database* dbb = tdbb->getDatabase();
CHECK_DBB(dbb);
jrd_rel* relation = rpb->rpb_relation;
RelationPages* relPages = relation->getPages(tdbb, rpb->rpb_transaction_nr);
WIN* window = &rpb->getWindow(tdbb);
// If there is a preferred page, try there first
PagesArray lowPages;
SLONG dp_primary = 0;
if (type == DPM_secondary)
{
USHORT pp_sequence;
SSHORT slot, line;
rpb->rpb_number.decompose(dbb->dbb_max_records, dbb->dbb_dp_per_pp, line, slot, pp_sequence);
const pointer_page* ppage =
get_pointer_page(tdbb, relation, relPages, window, pp_sequence, LCK_read);
if (ppage)
{
if (slot < ppage->ppg_count && ((dp_primary = ppage->ppg_page[slot])) )
{
CCH_HANDOFF(tdbb, window, dp_primary, LCK_write, pag_data);
UCHAR* space = find_space(tdbb, rpb, size, stack, record, type);
if (space)
return (rhd*) space;
if (!window->win_page.isTemporary()) {
CCH_get_related(tdbb, window->win_page, lowPages);
}
}
else {
CCH_RELEASE(tdbb, window);
}
}
}
// Look for space anywhere
for (USHORT pp_sequence = relPages->rel_data_space;; pp_sequence++)
{
relPages->rel_data_space = pp_sequence;
const pointer_page* ppage =
get_pointer_page(tdbb, relation, relPages, window, pp_sequence, LCK_read);
if (!ppage)
{
BUGCHECK(254);
// msg 254 pointer page vanished from relation list in locate_space
}
const SLONG pp_number = window->win_page.getPageNum();
const UCHAR* bits = (UCHAR *) (ppage->ppg_page + dbb->dbb_dp_per_pp);
for (USHORT slot = ppage->ppg_min_space; slot < ppage->ppg_count; slot++)
{
const SLONG dp_number = ppage->ppg_page[slot];
// hvlad: avoid creating circle in precedence graph, if possible
if (type == DPM_secondary && lowPages.exist(dp_number))
continue;
if (dp_number && ~bits[slot >> 2] & (1 << ((slot & 3) << 1)))
{
CCH_HANDOFF(tdbb, window, dp_number, LCK_write, pag_data);
UCHAR* space = find_space(tdbb, rpb, size, stack, record, type);
if (space)
return (rhd*) space;
window->win_page = pp_number;
ppage = (pointer_page*) CCH_FETCH(tdbb, window, LCK_read, pag_pointer);
}
}
const UCHAR flags = ppage->ppg_header.pag_flags;
CCH_RELEASE(tdbb, window);
if (flags & ppg_eof) {
break;
}
}
// Sigh. No space. Extend relation. Try for a while in case someone grabs the page
// before we can get it locked, then give up on the assumption that things
// are really screwed up.
UCHAR* space = 0;
int i;
for (i = 0; i < 20; ++i)
{
DPM_allocate(tdbb, window);
extend_relation(tdbb, relation, window);
space = find_space(tdbb, rpb, size, stack, record, type);
if (space) {
break;
}
}
if (i == 20) {
BUGCHECK(255); // msg 255 cannot find free space
}
if (record) {
record->rec_precedence.push(window->win_page.getPageNum());
}
#ifdef VIO_DEBUG
if (debug_flag > DEBUG_WRITES_INFO)
{
printf(" extended relation %d with page %"SLONGFORMAT" to get %d bytes\n",
relation->rel_id, window->win_page.getPageNum(), size);
}
#endif
return (rhd*) space;
}
Сторожа зацикливания здесь также на наблюдается.
В итоге.
Положительные аспекты проведенного результата:
- У IBProvider-а — реально хорошая тестовая система.
- IBProvider
выжилочень хорошо себя показал в этом тесте. И состояние незавершенного тестового процесса не показывает каких-либо признаков деградации. - Тестовое железо, хотя и приближается к 6-летнему юбилею, вполне даже ничего себе :). Хотя на i7, конечно, тесты отрабатывают как минимум в 2 раза быстрее.
Отрицательные аспекты:
- Я так и не прогнал тесты. Меня это печалит больше всего.
- Баги в Firebird.
Вообще, конечно, хотелось бы когда нибудь получить идеальное прохождение всех тестов. Но что-то мне подсказывает — не в этой жизни.
hvlad on 3 декабря, 2013
А сколько PP у этой таблицы ? См. в RDB$PAGES