From 3f31ec0739e6c4913ef59eebb0f8fb0798eee645 Mon Sep 17 00:00:00 2001 From: zotov Date: Thu, 30 Jun 2022 12:19:17 +0300 Subject: [PATCH] Added/Updated bugs\gh_6782_test.py. Checked on 3.0.8.33535, 4.0.1.2692, 5.0.0.509. --- tests/bugs/gh_6782_test.py | 468 +++++++++++++------------------------ 1 file changed, 164 insertions(+), 304 deletions(-) diff --git a/tests/bugs/gh_6782_test.py b/tests/bugs/gh_6782_test.py index f233c93a..e62b8c51 100644 --- a/tests/bugs/gh_6782_test.py +++ b/tests/bugs/gh_6782_test.py @@ -5,49 +5,144 @@ ID: issue-6782 ISSUE: 6782 TITLE: Getting "records fetched" for functions/procedures in trace DESCRIPTION: - Confirmed bug on 4.0.0.2436: there was no lines with numner of: - * number of fetched rows; - * additional info about number of fetches/reads/writes/marks (after elapsed time). + Confirmed bug on 4.0.0.2436, there was no: + * lines with number of fetched rows; + * additional info about number of fetches/reads/writes/marks (after elapsed time). - In other words, trace log: - * was before fix: - Procedure - 0 ms - * became after fix: - Procedure - 5 records fetched <<< --- added - 0 ms, 10 fetch(es) - ^^^^^^^^^^^^ --- added + In other words, trace log: + * was before fix: + Procedure + 0 ms + * became after fix: + Procedure + 5 records fetched <<< --- added + 0 ms, 10 fetch(es) + ^^^^^^^^^^^^ --- added - Test parses trace log and search there lines with names of known procedures/functions and - then checks presence of lines with number of fetched records (for selectable procedures) and - additional statistics ('fetches/reads/writes/marks'). - - Checked on: - 5.0.0.87 SS: 7.231s. - 5.0.0.85 CS: 6.425s. - 4.0.1.2520 SS: 6.929s. - 4.0.1.2519 CS: 9.452s. - 3.0.8.33476 SS: 12.199s. - 3.0.8.33476 CS: 14.090s. + Test parses trace log and search there lines with names of known procedures/functions and + then checks presence of lines with number of fetched records (for selectable procedures) and + additional statistics ('fetches/reads/writes/marks'). NOTES: -[29.06.2021] - Added delay for 1.1 second after ISQL finished its script and before we ask trace to stop. - This is the only way to make trace log be completed. DO NOT EVER remove this delay because fbsvcmgr - makes query to FB services only one time per SECOND. + [30.06.2022] pzotov + Checked on 3.0.8.33535, 4.0.1.2692, 5.0.0.509. - See also reply from Vlad related to test for core-6469, privately, letter: 04-mar-2021 13:02. FBTEST: bugs.gh_6782 """ +import locale +import re import pytest from firebird.qa import * -db = db_factory() +init_script = ''' + create table test(id int); + insert into test(id) select row_number()over() from rdb$types rows 5; + commit; + + set term ^; + create procedure standalone_selectable_sp returns(id int) as + begin + for select id from test as cursor c + do begin + update test set id = -id * (select count(*) from rdb$database) + where current of c; + suspend; + end + end + ^ + + create procedure standalone_nonselected_sp as + begin + for select id from test as cursor c + do begin + update test set id = -id * (select count(*) from rdb$database) + where current of c; + end + end + ^ + + create function standalone_func returns int as + begin + update test set id = rand()*10000000; + return (select max(id) from test); + end + ^ + + create package pg_test as + begin + procedure packaged_selectable_sp returns(id int); + function packaged_func returns int; + procedure packaged_nonselected_sp; + end + ^ + + create package body pg_test as + begin + procedure packaged_selectable_sp returns(id int) as + begin + for select id from test as cursor c + do begin + update test set id = -id * (select count(*) from rdb$database) + where current of c; + suspend; + end + end + + procedure packaged_nonselected_sp as + begin + for select id from test as cursor c + do begin + update test set id = -id * (select count(*) from rdb$database) + where current of c; + end + end + + function packaged_func returns int as + begin + update test set id = rand()*10000000; + return (select min(id) from test); + end + end + ^ + + + create procedure sp_main as + declare c int; + begin + for select id from standalone_selectable_sp into c do + begin + -- nop -- + end + ---------------------- + c = standalone_func(); + ---------------------- + execute procedure standalone_nonselected_sp; + ---------------------- + + for select id from pg_test.packaged_selectable_sp into c do + begin + -- nop -- + end + ---------------------- + c = pg_test.packaged_func(); + ---------------------- + + execute procedure pg_test.packaged_nonselected_sp; + end + ^ + set term ;^ + commit; + + --set list on; + --execute procedure sp_main; + --commit; +''' + +db = db_factory(init=init_script) act = python_act('db') -expected_stdout = """ +expected_stdout_trace = """ Procedure STANDALONE_SELECTABLE_SP: FOUND line with number of fetched records FOUND line with execution statistics @@ -72,279 +167,44 @@ expected_stdout = """ FOUND line with execution statistics """ -@pytest.mark.skip('FIXME: Not IMPLEMENTED') @pytest.mark.version('>=3.0.8') -def test_1(act: Action): - pytest.fail("Not IMPLEMENTED") +def test_1(act: Action, capsys): -# test_script_1 -#--- -# import os -# import re -# import subprocess -# from subprocess import Popen -# import time -# -# os.environ["ISC_USER"] = user_name -# os.environ["ISC_PASSWORD"] = user_password -# db_conn.close() -# -# #-------------------------------------------- -# -# def flush_and_close( file_handle ): -# # https://docs.python.org/2/library/os.html#os.fsync -# # If you're starting with a Python file object f, -# # first do f.flush(), and -# # then do os.fsync(f.fileno()), to ensure that all internal buffers associated with f are written to disk. -# global os -# -# file_handle.flush() -# if file_handle.mode not in ('r', 'rb') and file_handle.name != os.devnull: -# # otherwise: "OSError: [Errno 9] Bad file descriptor"! -# os.fsync(file_handle.fileno()) -# file_handle.close() -# -# #-------------------------------------------- -# -# def cleanup( f_names_list ): -# global os -# for i in range(len( f_names_list )): -# if type(f_names_list[i]) == file: -# del_name = f_names_list[i].name -# elif type(f_names_list[i]) == str: -# del_name = f_names_list[i] -# else: -# print('Unrecognized type of element:', f_names_list[i], ' - can not be treated as file.') -# print('type(f_names_list[i])=',type(f_names_list[i])) -# del_name = None -# -# if del_name and os.path.isfile( del_name ): -# os.remove( del_name ) -# -# #-------------------------------------------- -# -# -# # Prepare config for trace session that will be launched by call of FBSVCMGR: -# ################ -# txt = '''database= %[\\\\\\\\/]bugs.gh_6782.fdb -# { -# enabled = true -# time_threshold = 0 -# log_initfini = false -# log_errors = true -# log_procedure_finish = true -# log_function_finish = true -# } -# ''' -# trc_cfg=open( os.path.join(context['temp_directory'],'tmp_trace_6782.cfg'), 'w') -# trc_cfg.write(txt) -# flush_and_close( trc_cfg ) -# -# ##################################################################### -# # Async. launch of trace session using FBSVCMGR action_trace_start: -# -# trc_log = open( os.path.join(context['temp_directory'],'tmp_trace_6782.log'), 'w') -# -# # Execute a child program in a new process, redirecting STDERR to the same target as of STDOUT: -# p_trace = Popen( [context['fbsvcmgr_path'], "localhost:service_mgr", -# "action_trace_start","trc_cfg", trc_cfg.name], -# stdout=trc_log, stderr=subprocess.STDOUT) -# -# # Wait! Trace session is initialized not instantly! -# time.sleep(1) -# -# ##################################################################### -# -# # Determine active trace session ID (for further stop): -# trc_lst = open( os.path.join(context['temp_directory'],'tmp_trace_6782.lst'), 'w') -# subprocess.call([context['fbsvcmgr_path'], "localhost:service_mgr", -# "action_trace_list"], -# stdout=trc_lst, stderr=subprocess.STDOUT -# ) -# flush_and_close( trc_lst ) -# -# # Session ID: 5 -# # ... -# trcssn = None -# with open( trc_lst.name,'r') as f: -# for line in f: -# if 'Session ID' in line and len(line.split())>=3: -# trcssn = line.split()[2] -# break -# -# # Result: `trcssn` is ID of active trace session. -# if not trcssn: -# print("Error parsing trace session ID.") -# flush_and_close( trc_log ) -# -# else: -# ##################################################################### -# -# # Preparing script for ISQL: -# -# sql_cmd=''' -# create table test(id int); -# insert into test(id) select row_number()over() from rdb$types rows 5; -# commit; -# -- set echo on; -# set term ^; -# create procedure standalone_selectable_sp returns(id int) as -# begin -# for select id from test as cursor c -# do begin -# update test set id = -id * (select count(*) from rdb$database) -# where current of c; -# suspend; -# end -# end -# ^ -# -# create procedure standalone_nonselected_sp as -# begin -# for select id from test as cursor c -# do begin -# update test set id = -id * (select count(*) from rdb$database) -# where current of c; -# end -# end -# ^ -# -# create function standalone_func returns int as -# begin -# update test set id = rand()*10000000; -# return (select max(id) from test); -# end -# ^ -# -# create package pg_test as -# begin -# procedure packaged_selectable_sp returns(id int); -# function packaged_func returns int; -# procedure packaged_nonselected_sp; -# end -# ^ -# -# create package body pg_test as -# begin -# procedure packaged_selectable_sp returns(id int) as -# begin -# for select id from test as cursor c -# do begin -# update test set id = -id * (select count(*) from rdb$database) -# where current of c; -# suspend; -# end -# end -# -# procedure packaged_nonselected_sp as -# begin -# for select id from test as cursor c -# do begin -# update test set id = -id * (select count(*) from rdb$database) -# where current of c; -# end -# end -# -# function packaged_func returns int as -# begin -# update test set id = rand()*10000000; -# return (select min(id) from test); -# end -# end -# ^ -# -# -# create procedure sp_main as -# declare c int; -# begin -# for select id from standalone_selectable_sp into c do -# begin -# -- nop -- -# end -# ---------------------- -# c = standalone_func(); -# ---------------------- -# execute procedure standalone_nonselected_sp; -# ---------------------- -# -# for select id from pg_test.packaged_selectable_sp into c do -# begin -# -- nop -- -# end -# ---------------------- -# c = pg_test.packaged_func(); -# ---------------------- -# -# execute procedure pg_test.packaged_nonselected_sp; -# end -# ^ -# set term ;^ -# commit; -# -# set list on; -# execute procedure sp_main; -# commit; -# ''' -# -# isql_cmd=open( os.path.join(context['temp_directory'],'tmp_isql_6782.sql'), 'w') -# isql_cmd.write(sql_cmd) -# flush_and_close( isql_cmd ) -# -# ####################################################################### -# isql_log=open( os.path.join(context['temp_directory'],'tmp_isql_6782.log'), 'w') -# subprocess.call( [ context['isql_path'], dsn, "-i", isql_cmd.name ], stdout=isql_log,stderr=subprocess.STDOUT) -# flush_and_close( isql_log ) -# -# ######################### -# ### C R U C I A L ### -# ######################### -# # We must stay idle here at least 1.1 second before ask fbsbcmgr to stop trace. -# # The reason is that fbsvcmgr make query to FB services only one time per second. -# # If we do not take delay here then test can fail with (most often) empty log -# # or its log can look incompleted. -# # See letter from Vlad, 04-mar-2021 13:02 (subj: "Test core_6469 on Linux..."). -# ############### -# time.sleep(1.1) -# ############### -# -# # Stop trace session. We have to do this BEFORE we termitane process with PID = p_trace. -# # NOTE ONCE AGAIN: we can do this only after delay for at least 1.1 second! -# trc_lst=open(trc_lst.name, "a") -# trc_lst.seek(0,2) -# subprocess.call([ context['fbsvcmgr_path'], "localhost:service_mgr", -# "action_trace_stop","trc_id",trcssn], -# stdout=trc_lst, stderr=subprocess.STDOUT -# ) -# flush_and_close( trc_lst ) -# -# ########################### -# p_trace.terminate() -# flush_and_close( trc_log ) -# ########################### -# -# # Check logs: -# ############# -# allowed_patterns = ( -# re.compile('Procedure\\s+(STANDALONE_SELECTABLE_SP:|STANDALONE_NONSELECTED_SP:|PG_TEST.PACKAGED_SELECTABLE_SP:|PG_TEST.PACKAGED_NONSELECTED_SP:|SP_MAIN:)', re.IGNORECASE) -# ,re.compile('Function\\s+(STANDALONE_FUNC:|PG_TEST.PACKAGED_FUNC:)', re.IGNORECASE) -# ,re.compile('\\d+\\s+record(s|\\(s\\))?\\s+fetched', re.IGNORECASE) -# ,re.compile('\\s+\\d+\\s+ms(,)?\\s+\\d+\\s+fetch(es|\\(es\\))((,)?\\s+\\d+\\s+read(s|\\(s\\)))?((,)?\\s+\\d+\\s+write(s|\\(s\\)))?(,)?\\s+\\d+\\s+mark(s|\\(s\\))', re.IGNORECASE) -# ) -# -# with open(trc_log.name) as f: -# for line in f: -# if line.split(): -# match2some = filter( None, [ p.search(line) for p in allowed_patterns ] ) -# if match2some: -# if ' ms' in line and 'fetch' in line: -# print('FOUND line with execution statistics') -# elif 'record' in line and 'fetch' in line: -# print('FOUND line with number of fetched records') -# else: -# print(line) -# -# # Cleanup: -# time.sleep(1) -# cleanup( (trc_lst, trc_cfg, trc_log, isql_cmd, isql_log) ) -# -#--- + trace_cfg_items = [ + 'time_threshold = 0', + 'log_errors = true', + 'log_procedure_finish = true', + 'log_function_finish = true', + ] + + + sql_run=''' + set list on; + execute procedure sp_main; + ''' + + with act.trace(db_events = trace_cfg_items, encoding=locale.getpreferredencoding()): + act.isql(input = sql_run, combine_output = True) + + allowed_patterns = \ + ( + r'Procedure\s+(STANDALONE_SELECTABLE_SP:|STANDALONE_NONSELECTED_SP:|PG_TEST.PACKAGED_SELECTABLE_SP:|PG_TEST.PACKAGED_NONSELECTED_SP:|SP_MAIN:)' + ,r'Function\s+(STANDALONE_FUNC:|PG_TEST.PACKAGED_FUNC:)' + ,r'\d+\s+record(s|\(s\))?\s+fetched' + ,r'\s+\d+\s+ms(,)?\s+\d+\s+fetch(es|\(es\))((,)?\s+\d+\s+read(s|\(s\)))?((,)?\s+\d+\s+write(s|\(s\)))?(,)?\s+\d+\s+mark(s|\(s\))' + ) + allowed_patterns = [ re.compile(p, re.IGNORECASE) for p in allowed_patterns ] + + for line in act.trace_log: + if line.split(): + if act.match_any(line, allowed_patterns): + if ' ms' in line and 'fetch' in line: + print('FOUND line with execution statistics') + elif 'record' in line and 'fetch' in line: + print('FOUND line with number of fetched records') + else: + print(line) + + act.expected_stdout = expected_stdout_trace + act.stdout = capsys.readouterr().out + assert act.clean_stdout == act.clean_expected_stdout