Я написал компонент, который выполняет серию динамически формируемых запросов к базе данных и в конечном итоге выполняет окончательный запрос, результаты которого извлекаются. Вся эта логика завернута в генератор. Другие компоненты могут подключаться к этому генератору и буферизовать результаты в файл, текстовый файл с разделителями табуляцией в случае этого теста. Вот код функции генератора:
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
из курсора.
Спасибо заранее.