Производительность запросов SQLITE слишком сильно отличается, чтобы быть надежной или понятной - PullRequest
5 голосов
/ 19 июля 2011

Краткая версия проблемы.

Иногда запрос (который использует индексы), который обычно выполняется за секунду, занимает минуту или даже больше, чтобы выполнить .EXPLAIN показывает, что полное сканирование таблицы не было выполнено.База данных большая (2 Гб, 4,5 млн записей) и используется исключительно.Повторно выполнить тот же запрос быстро.До какого-то особенного момента ...

Длинная версия проблемы.

У меня есть база данных журнала на SQLITE:

    CREATE TABLE log( id integer primary key autoincrement,
  msg text,
  created_at int,
  kind text,
  computer text,
  process text,
  who text
  );
    CREATE INDEX idxlog_created_at ON log(created_at);
    CREATE INDEX idxlog_kind_computer_id ON log(kind,computer,id);
    CREATE INDEX idxlog_kind_computer_process_id ON log(kind,computer,process,id);
    CREATE INDEX idxlog_kind_computer_process_who_id ON log(kind,computer,process,who,id);
    CREATE INDEX idxlog_kind_id ON log(kind,id);

kind ===>'debug', 'error', 'warn', 'info'
computer ===> имя компьютера
process ===> имя процесса
who ===> имя компонента (отправившего сообщениев журнал)

Индексы создаются для обеспечения быстрого ответа на любой возможный запрос к журналу.Столбец id включен в индексы для обеспечения быстрого ORDER BY.

Sqlite: 3.7.7.1
Платформа: Windows XP
Язык: Delphi через sqlite3.dll (из sqlite.org)
Pragmas(для данного конкретного соединения):

PRAGMA encoding = "UTF-8"; 
  PRAGMA foreign_keys = ON; 
  PRAGMA synchronous = NORMAL; 
  PRAGMA page_size = 8192; 
  PRAGMA automatic_index = 0;
  PRAGMA temp_store = FILE;

Открытие соединения SQLITE:

SQLite3_Open_v2(@UTF8String(AFileName)[1], Fdb,
    SQLITE_OPEN_READWRITE or
    SQLITE_OPEN_CREATE or
    SQLITE_OPEN_PRIVATECACHE or
    SQLITE_OPEN_NOMUTEX
  );

Пример запроса журнала:

SELECT 
   1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log  
WHERE id > 4149245 AND id <= 9223372036854775807 AND kind = 'error' 

UNION ALL

SELECT 
   1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log  
WHERE id > 4149245 AND id <= 9223372036854775807 AND kind = 'debug' 

UNION ALL

 SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
 FROM log  
 WHERE id > 4149245 AND id <= 9223372036854775807 AND kind = 'timing' 

ORDER BY id DESC LIMIT 100

Каждый запросявляется СОЮЗОМ запроса по виду для обеспечения использования индексов.

В базе данных ~ 4,5 млн записей, размер файла базы данных ~ 1,8 Гб.База данных используется исключительно для процесса регистрации (во время этих измерений не было выполнено никаких дополнительных операций регистрации).

Теперь проблема .

Иногда производительность такогозапрос примерно на 100 медленнее, чем «обычная» производительность.

Обычная производительность на меньше секунды .Теперь я сделал тайминги и сохранил информацию о длительных запросах.Вот вы:

    SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log _computer_process_id  
WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'error' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log _computer_process_id  
WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'warn' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log _computer_process_id  
WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'info' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log _computer_process_id  
WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'debug' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
FROM log _computer_process_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'timing' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  

ORDER BY id DESC LIMIT 100

план: 4,0,0, Журнал ПОИСКА ТАБЛИЦЫ AS _computer_process_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_id (kind =? AND computer =? AND process =?) (~ 2 строки) 5,0, 0, ЖУРНАЛ ПОИСКА ТАБЛИЦЫ КАК _computer_process_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_id (kind =? AND computer =? AND process =?) (~ 2 строки) 3,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 4 И 5 (UNION ALL) 6,0,0,Журнал ПОИСКА ТАБЛИЦЫ КАК _computer_process_id ИСПОЛЬЗОВАНИЕ ИНДЕКСА idxlog_kind_computer_process_id (kind =? AND computer =? AND process =?) (~ 2 строки) 2,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 3 И 6 (UNION ALL) 7,0,0, журнал SEARCH TABLEAS _computer_process_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_id (kind =? AND computer =? AND process =?) (~ 2 строки) 1,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 2 И 7 (UNION ALL) 8,0,0, Журнал ПОИСКА ТАБЛИЦЫ AS _computer_process_id USINGINDEX idxlog_kind_computer_process_id (kind =? AND computer =? AND process =?) (~ 2 строки) 0,0,0, СОЕДИНЕННЫЕ ПОДКВЕТКИ 1 И 8 (UNION ALL)

61326 мс

  SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'error' AND computer='KRAFTWAY'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'warn' AND computer='KRAFTWAY'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'debug' AND computer='KRAFTWAY'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'timing' AND computer='KRAFTWAY'  ORDER BY id DESC LIMIT 100

план: 3,0,0, ПОИСК ТАБЛИЦА журнал AS _computer_id ИСПОЛЬЗОВАНИЕ ИНДЕКСА idxlog_kind_computer_id (kind =?И компьютер =?) (~ 2 строки) 4,0,0, Журнал ПОИСКА ТАБЛИЦЫ КАК _computer_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_id (kind =? И компьютер =?) (~ 2 строки) 2,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 3 И 4 (UNION ALL) 5,0,0, журнал SEARCH TABLE AS _computer_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_id (kind =? AND computer =?) (~ 2 строки) 1,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 2 И 5 (UNION ALL) 6,0,0, Журнал ПОИСКА ТАБЛИЦЫ КАК _computer_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_id (kind =? AND computer =?) (~ 2 строки) 0,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 1 И 6 (UNION ALL)

45643 мс

     SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_process_who_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'error' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  AND who='main(TMessageRouter)'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_process_who_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'warn' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  AND who='main(TMessageRouter)'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_process_who_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'info' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  AND who='main(TMessageRouter)'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_process_who_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'debug' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  AND who='main(TMessageRouter)'  

UNION ALL 

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id FROM log _computer_process_who_id  WHERE id > 4149246 AND id <= 9223372036854775807 AND kind = 'timing' AND computer='KRAFTWAY'  AND process='D:\xxx.exe'  AND who='main(TMessageRouter)'  

ORDER BY id DESC LIMIT 100

план: 4,0,0, журнал SEARCH TABLE AS _computer_process_who_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_who_id (kind =? AND computer =? AND process =? AND who =?) (~ 2 строки)5,0,0, Журнал ПОИСК ТАБЛИЦЫ КАК _computer_process_who_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_who_id (kind =? AND computer =? AND process =? AND who =?) (~ 2 строки) 3,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 4 И 5 (UNION ALL) 6,0,0, Журнал ПОИСКА ТАБЛИЦЫ КАК _computer_process_who_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_who_id (kind =?И компьютер =?И процесс =?И кто =?) (~ 2 строки) 2,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 3 И 6 (UNION ALL) 7,0,0, Журнал ПОИСКА ТАБЛИЦЫ КАК _computer_process_who_id ИНДЕКС ИСПОЛЬЗОВАНИЯ idxlog_kind_computer_process_who_id (kind =? AND computer =? AND computer =? AND process = = И процесс =? И кто =?) (~ 2 строки)1,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 2 И 7 (UNION ALL) 8,0,0, Журнал ПОИСКА ТАБЛИЦЫ КАК _computer_process_who_id ИСПОЛЬЗОВАНИЕ INDEX idxlog_kind_computer_process_who_id (kind =? AND computer =? AND process =? AND who =?) (~ 2 строки) 0,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 1 И 8 (UNION ALL)

175899 мс

Да, этот запрос выполнялся 3 минуты .

Видите план после каждого запроса? Правильно, после каждого слишком длинного запроса я выполнял «EXPLAIN QUERY PLAN» + SQL запроса и сохранял результат. Никто не может ясно увидеть, что в плане нет SCAN. Это означает, что сканирование FULL TABLE не выполняется, индексы используются, и все в порядке.

Да, все в порядке, кроме времени запроса.

Мониторинг процесса ведения журнала во время такого длительного запроса показывает постоянный дисковый ввод-вывод со скоростью около 1 МБ / с (что, очевидно, не является узким местом, жесткий диск может выполнять 100 МБ / с) и примерно нулевую активность ЦП. Если приостановлено под отладчиком, длительный поток находится глубоко внутри sqlite.dll и заканчивается на ntdll.ZwReadFile.

Я все испробовал и дефрагментировал. Он работает быстрее, но проблема остается.

И если я перезапущу тот же запрос, он выполняется почти сразу.

Та же база данных, тот же запрос. Первый запуск - 160 секунд, второй запуск - 2 секунды.

Еще один интересный факт: самые длительные запросы часто не возвращают строк.

Да, я понимаю, что кеширование и ОС хранит некоторые страницы в памяти.

Все в порядке со мной. Я не понимаю, почему SQLITE читает так медленно, если ему нужны страницы? Зачем читать со скоростью 1 мб в секунду? Являются ли данные слишком разбросанными внутри базы данных SQLITE, поэтому есть много запросов? Тогда почему? Индексы используются, чтобы убедиться, что это не проблема, не так ли?

Я совершенно невежествен и благодарен за любую помощь.

UPDATE.

ВЫБЕРИТЕ 1 как сегодня, id как rowid, kind, who, msg, computer, process, creation_at, id ОТ журнала WHERE ID> 4033214 И идентификатор <= 9223372036854775807 И вид = 'ошибка' И компьютер = 'KRAFTWAY' И процесс = 'D: \ xxx.exe' </p>

UNION ALL

ВЫБЕРИТЕ 1 как сегодня, id как rowid, kind, who, msg, computer, process, creation_at, id ОТ журнала WHERE ID> 4033214 И идентификатор <= 9223372036854775807 И вид = 'предупреждение' И компьютер = 'KRAFTWAY' И процесс = 'D: \ xxx.exe' </p>

UNION ALL

ВЫБЕРИТЕ 1 как сегодня, id как rowid, kind, who, msg, computer, process, creation_at, id ОТ журнала WHERE ID> 4033214 И идентификатор <= 9223372036854775807 И вид = 'информация' И компьютер = 'KRAFTWAY' И процесс = 'DD: \ xxx.exe' </p>

UNION ALL

ВЫБЕРИТЕ 1 как сегодня, id как rowid, kind, who, msg, computer, process, create_at, id ОТ журнала WHERE ID> 4033214 И ID <= 9223372036854775807 И вид = 'отладка' И компьютер = 'KRAFTWAY' И процесс = 'D: \ xxx.exe' </p>

UNION ALL

ВЫБЕРИТЕ 1 как сегодня, id как rowid, kind, who, msg, computer, process, creation_at, id ИЗ журнала, ГДЕ id> 4033214 И id <= 9223372036854775807 И вид = 'хронометраж' И компьютер = 'KRAFTWAY' И процесс = 'D: \ xxx.exe' </p>

ЗАКАЗАТЬ ПО ID DESC LIMIT 100

план: 4,0,0, Журнал ПОИСКА ТАБЛИЦЫ С ИСПОЛЬЗОВАНИЕМ ИНДЕКСА ПОКРЫТИЯ idxlog_kind_computer_process_id_who_msg_created_at (kind =? AND computer =? AND process =?) (~ 2 строки) 5,0,0, Журнал ПОИСКА ТАБЛИЦЫ С ИСПОЛЬЗОВАНИЕМ ИНДЕКСА ПОКРЫТИЯ idxlog_kind_computer_process_id_who_msg_created_at (kind =? AND computer =? AND process =?) (~ 2 строки) 3,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 4 И 5 (UNION ALL) 6,0,0, Журнал ПОИСКА ТАБЛИЦЫ С ИСПОЛЬЗОВАНИЕМ ИНДЕКСА ПОКРЫТИЯ idxlog_kind_computer_process_id_who_msg_created_at (kind =? AND computer =? AND process =?) (~ 2 строки) 2,0,0, СОЕДИНИТЕЛЬНЫЕ ПОДПИСИ 3 И 6 (UNION ALL) 7,0,0, Журнал ПОИСКА ТАБЛИЦЫ С ИСПОЛЬЗОВАНИЕМ ИНДЕКСА ПОКРЫТИЯ idxlog_kind_computer_process_id_who_msg_created_at (kind =? AND computer =? AND process =?) (~ 2 строки) 1,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 2 И 7 (UNION ALL) 8,0,0, Журнал ПОИСКА ТАБЛИЦЫ С ИСПОЛЬЗОВАНИЕМ ИНДЕКСА ПОКРЫТИЯ idxlog_kind_computer_process_id_who_msg_created_at (kind =? AND computer =? AND process =?) (~ 2 строки)0,0,0, СОЕДИНЕННЫЕ ПОДПИСИ 1 И 8 (UNION ALL)

1138669 мс Это ~ 18 минут.

Повторный запрос: менее 100 мс.

В течение этих 18 минут процесс чтения базы данных производился со скоростью около 500 Кбайт / с.

Ответы [ 2 ]

1 голос
/ 22 сентября 2011

Я полагаю, что вы получаете OK от

PRAGMA integrity_check

Вы действительно устанавливаете эксклюзивную блокировку?

PRAGMA locking_mode = EXCLUSIVE

Можете ли вы воспроизвести проблему в небольшой базе данных с той же схемой и запросамипросто меньше данных?

0 голосов
/ 22 сентября 2011

Не могли бы вы:

CREATE INDEX i_informations ON log (computer ASC, process ASC, id DESC);

SELECT 1 as today, id as rowid, kind,who,msg,computer,process,created_at,id 
  FROM log _computer_process_id  
 WHERE id BETWEEN 4149247 AND 9223372036854775807
   AND kind IN ('info','debug','timing')
   AND computer='KRAFTWAY'
   AND process='D:\xxx.exe'  
 ORDER BY id DESC limit 100
...