Большое тестирование #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:

Database File Properties

Формально — в базе нет никаких данных. Потому что все тесты, за редким исключением, удаляют свои тестовые записи.

Состояние серверного процесса.

FB Process. Image Info.
Информация о серверном процессе.

FB Process. Image State.
Ресурсы серверного процесса на 3 декабря.

FB Process. Image State. November 16.
Ресурсы серверного процесса на 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:

[THR:005516] [16.11.2013 23:01:39] ERROR: [blob|blob.002.cmd.enable_defer_data.unicode.TBL_CS__UTF8.COL_BLOB.param_adLongVarWChar.bind__wstr_byref.small.len_2.chars_WIN1251.ins_UNICODE_FSS.sel_UNICODE_FSS] Wrong number of deleted records: 110. Wait: 255. IDs range [2718136087..2718136341].

Поскольку тест завершился по ошибке, он откатил операцию удаления и записи остались в базе данных.

Выборка из этого диапазона возвращает все 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.

Вообще, конечно, хотелось бы когда нибудь получить идеальное прохождение всех тестов. Но что-то мне подсказывает — не в этой жизни.

19 комментариев

hvlad  on Декабрь 3rd, 2013

А сколько PP у этой таблицы ? См. в RDB$PAGES

Kovalenko  on Декабрь 4th, 2013

Хай.

Запрос "select RDB$PAGE_TYPE, count(*) from RDB$PAGES where RDB$RELATION_ID=179 group by 1;" возвращает:

4 — 66145 (pag_pointer)
6 — 1 (pag_root)

dimitr  on Декабрь 4th, 2013

т.е. получено переполнение USHORT для pp_sequence, из-за чего и зацикливаемся. Вот только на самом деле причина возникла ранее и называется она переполнение recno/dbkey (ага, снова, просто перешли от 35 гиг к терабайтам). Что странно, это то что нет диагностики на эту тему. Либо она некачественная.

Kovalenko  on Декабрь 4th, 2013

Хай.

Страницы у вас там нумеруются LONG-ом.

То есть всего может быть 2147483648 страниц(?)

В случае страницы размером 16KB:
На одной pointer-странице помещается 4KB указателей (по 4 байта на указатель). То есть для все базы нужно (грубо говоря) 524288 pointer-страниц.

А если размер страницы равен 4KB — то pointer-страниц нужно в 4 раза больше.

USHORT, используемый для нумерации pointer-страниц — это всего 65536. То есть, как минимум (для страниц размером 16KB) в 8 раз меньше чем требуется (524288).

Я все правильно посчитал? 🙂

dimitr  on Декабрь 4th, 2013

лимит в 64К pointer pages он для каждой таблицы, а не для всей базы

dimitr  on Декабрь 4th, 2013

если я правильно с утра соображаю (что под вопросом), то для страницы 4КБ имеем: 64К * 4КБ / 4 * 4КБ = 256ГБ на таблицу (min) и для страницы 16КБ имеем: 64К * 16КБ / 4 * 16КБ = 4ТБ на таблицу (max). На твоей базе со страницей 8КБ лимит будет 1ТБ на таблицу или 128 млн data pages. Но у тебя таблица всего 1 млн data pages, судя по gstat-у. Так что до лимита тут еще ой как далеко…

dimitr  on Декабрь 4th, 2013

т.е. счетчик PP почему-то переполнился много ранее ожидаемого…

Kovalenko  on Декабрь 4th, 2013

Подсчеты вроде правильные (я пересчитал) 🙂

>Но у тебя таблица всего 1 млн data pages, судя по gstat-у.

А страницы под блобы и массивы, которые я в эту таблицу пихал — они что, не подсчитываются?

dimitr  on Декабрь 4th, 2013

в 3-ке точно подсчитываются, в 2.5 вроде выводится только число страниц под «большие блобы» (более страницы). Влад точнее скажет.

dimitr  on Декабрь 4th, 2013

ЗЫ. gstat надо было с ключом -r запускать

hvlad  on Декабрь 4th, 2013

В 2-х словах — gstat в 2.5 страницы с блобами\массивами не считает.

Я видел, что gstat показывает 1.1 млн DP и мне сразу показалось это странным, т.к. листьев индекса он показывает в 4 раза больше, что есть ооочень не типично. Поэтому я и спросил про кол-во PP и мы убедились, что оно больше чем 64K, что и требовалось узнать.

Переполнения номера записи там нет (рано ещё), но т.к. USHORT’ы для pp_sequence повсюду, то имеем то, что имеем. Исправим, не проблема.

PS Если бы кто-то собирал мусор во время теста, то и проблемы бы не было, и до терабайта не дорос бы 😉

hvlad  on Декабрь 4th, 2013

А проверь ещё firebird.log на наличие записей о свипе, плс

Kovalenko  on Декабрь 4th, 2013

>А проверь ещё firebird.log на наличие записей о свипе, плс

Для этой базы таких записей в логе нет.

Есть для другой базы. То есть, свип иногда запускается:

HOME2 Fri Sep 27 14:51:03 2013
Sweep is finished
Database «D:\DATABASE\IBP_TEST_FB25_D3.GDB»
OIT 105403, OAT 105642, OST 105638, Next 105647

——
Насчет «Если бы кто-то собирал мусор во время теста».

Пока я не прикрутил пул подключений к тестовой системе, проблем с ростом объема базы данных не было как таковых.

hvlad  on Декабрь 4th, 2013

1.1 млн DP\slot’s при > 64K PP я могу объяснить только тем, что бОльшая часть PP пуста (пустые PP не освобождаются), т.е. мусор таки собирался, но уже после того, как кол-во PP выросло выше 64К

Kovalenko  on Декабрь 4th, 2013

>gstat надо было с ключом -r запускать

«gstat -a -r -t TBL_CS__UTF8 -u gamer -p vermut localhost:d:\database\ibp_test_fb25_d3_2.gdb»

Пересчитал и обновил в основном тексте 🙂

Kovalenko  on Декабрь 8th, 2013

Думаю, тесты все равно до конца бы не добежали. На финише они по-любому бы завалили сервер:

[THR:033516] [08.12.2013 03:23:53] ERROR: … Ошибка подготовки SQL выражения.

Unable to complete network request to host «localhost».
Error writing data to the connection.
Result code=DB_E_ERRORSINCOMMAND

Бага описана в трекере 28 сентября.

Но как говорил известный товарищь — «попытка не пытка» :).

Вести с полей  on Май 23rd, 2016

[…] точка предыдущего отказа еще не пройдена — количество тестов «немного» […]

Большое тестирование #4  on Май 31st, 2016

[…] машина так же, что и в прошлый раз — Q6600 / 8GB / выделенный массив 4x1TB WD RE4 в RAID0 на RS2BL040. […]

Вести с полей.  on Июль 24th, 2016

[…] была пройдена критическая точка, в которой произошло зацикливание. Окучено ~660 тысяч […]

Оставить комментарий