Зацикливание курсора cx_Oracle останавливается на несколько минут

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

def cycle(self, schema, matchprofile, fixedcond):

    cursor = self.cursor
    cursor.set_schema(schema)
    cursor.execute('TRUNCATE TABLE schema.table')
    metaatts = self.get_metaattributes(schema)

    for condset in matchprofile:
        condsql = self.dostuffwith(self, matchprofile, fixedcond)
        qry = self.qrybase.replace('<<condset>>', condset).replace('<<condsql>>', condsql)
        cursor.execute(qry)             # queries performing logic aganst database

    cursor.execute(self.finalqry)           # select query extracting results

    for row in cursor:
        yield Row(row, metaatts.copy())

    if self.counts:
        self.counter.addto(cursor.rowcount)

cursor — это подкласс cx_Oracle.Cursor с увеличенными arraysize и outputtypehandler, который преобразует строки в Unicode. cycle вызывается из другого метода, который объединяет выходные данные для нескольких входных схем в один поток.

cycles = itertools.imap(self.cycle, schemas, itertools.repeat(matchprofile), itertools.repeat(fixedcond))
rows = itertools.chain.from_iterable(cycles)

Я запускаю это на Python 2.6.

Я запускал весь сценарий уже десятки раз, и в большинстве случаев на выполнение схемы базы данных уходило от 11 до 12 минут. Это намного больше, чем ожидалось. Неожиданно для меня в некоторых попытках скрипт выполнялся примерно за 55 секунд. Это как раз то, что я ожидал, исходя из производительности устаревшего сценария, который я пытаюсь заменить.

Поскольку новый инструмент может принимать несколько схем базы данных в качестве входных параметров, я также провел тест с предоставлением одной и той же схемы шесть раз. Зарегистрированное время выполнения показало, что проблема возникла только на первой итерации:

:: 1597 records in 11:33
:: 1597 records in 0:56
:: 1597 records in 0:55
:: 1597 records in 0:55
:: 1597 records in 0:55
:: 1597 records in 0:55

:: total 9582 records in 16:10

Мне также удалось профилировать прогоны, которые дали разумный...

109707 function calls (109627 primitive calls) in 57.938 CPU seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    12   56.154    4.679   56.154    4.680 {function execute at 0x010074B0}
     1    0.819    0.819    0.819    0.819 ora.py:194(__init__)
     1    0.387    0.387    0.387    0.387 {function parse at 0x010075B0}
  1598    0.331    0.000   56.543    0.035 DuplicateDetector.py:219(cycle)
  1598    0.118    0.000    0.118    0.000 {method 'writerow' of '_csv.writer' objects}
 30295    0.029    0.000    0.029    0.000 {_codecs.utf_8_decode}
  1598    0.025    0.000   56.720    0.035 dsv.py:146(generate)
 30310    0.022    0.000    0.029    0.000 {method 'encode' of 'unicode' objects}

... и чрезмерное время.

109707 function calls (109627 primitive calls) in 701.093 CPU seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  1598  644.514    0.403  699.827    0.438 DuplicateDetector.py:219(cycle)
    12   55.247    4.604   55.248    4.604 {function execute at 0x010084B0}
     1    0.783    0.783    0.783    0.783 ora.py:194(__init__)
     1    0.283    0.283    0.283    0.283 {function parse at 0x010085B0}
  1598    0.121    0.000    0.121    0.000 {method 'write' of '_csv.writer' objects}
 30295    0.036    0.000    0.036    0.000 {_codecs.utf_8_decode}
  1598    0.025    0.000  700.006    0.438 dsv.py:146(generate)
 30310    0.022    0.000    0.028    0.000 {method 'encode' of 'unicode' objects}
 30295    0.021    0.000    0.057    0.000 utf_8.py:15(decode)

Понятно, что если в первом случае операции с базой данных занимают большую часть времени выполнения, то во втором большая часть времени тратится на генератор cycle. Я использовал отладчик Idle, чтобы выполнить это шаг за шагом, и кажется, что строка for row in cursor: отвечает примерно за 10 минут выполнения. Я также заметил, что использование памяти процессом python.exe в это время постоянно увеличивается.

Теперь вопрос, что происходит в этой строке, что время выполнения одного и того же кода настолько разное (хотя вполне повторяемое)? Какие операции внутри cx_Oracle выполняет, когда Cursor используется в качестве итератора? Какие ошибки я мог сделать в коде упаковки, которые вызывают это? По общему признанию, я никогда не видел ничего подобного со старым скриптом, который не использовал классы и генераторы, а просто выполнял fetchall из курсора.

Спасибо заранее.


person gdabski    schedule 14.04.2013    source источник


Ответы (1)


Не знаю, относится ли это к вашей проблеме, но вчера я столкнулся с серьезной проблемой производительности при установке большого размера массива для курсора.

У меня было два метода с использованием cursor.fetchall() и cursor.fetchmany().

Для завершения cursor.fetchall() требовалось 0,1 секунды, для cursor.fetchmany() — 1,5 секунды.

После некоторой отладки я заметил, что устанавливаю для cursor.arraysize большое значение (100 000) перед fetch_many(). Это приводит к тому, что драйвер cxOracle выделяет пространство памяти для количества строк, равного размеру массива. В сочетании с запросом с большим количеством столбцов varchar2 (4000) это в сумме дает некоторое количество x * 100 МБ, которое выделяется перед каждым вызовом, а затем освобождается.

Может быть и твоя проблема.

person Nutiu Lucian    schedule 30.09.2013