New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
FBSVCMGR with action_trace_stop
does not verify that trace log is ENTIRELY written on disk before returning control to outer environment [CORE4896]
#5189
Comments
Modified by: @pavel-zotovdescription: It looks like very unpleasant "feature" that FBSVCMGR with action_trace_stop can return control to outer environment (batch or fbtest) without checking that OS really has finished writing of log. Consider following batch (be sure that you have standard utility for comparing text files - 'fc.exe' on Windows): === start of batch `fbsvc_check.bat` === cls set fbhome=C:\1INSTALL\FIREBIRD\fb30sS set fbscfg=%~n0.cfg.tmp del %fbscfg% 2>nul echo services>> %fbscfg% set estlog=%~n0.est.log set actlog=%~n0.act.log echo %dbtest% %dbbkup% >>%estlog% set str=%fbsrun% action_trace_start trc_cfg %fbscfg% 1^>%fbslog% 2^>^&1 ping -n 2 127.0.0.1>nul @Rem Do some actions which should be written into trace log: @echo --- BACKUP --- @echo --- RESTORE --- @echo --- STATISTICS of sys relations --- @echo --- STATISTICS of header --- @echo --- PROPERTIES: update FW --- @echo --- PROPERTIES: update BUFFERS number --- @echo --- PROPERTIES: update SWEEP interval --- @echo --- PROPERTIES: change SQL DIALECT --- @echo --- PROPERTIES: make database READ-ONLY --- @echo --- PROPERTIES: return database to READ-WRITE --- %fbsrun% action_trace_list 1>%fbslst% 2>&1 for /f "tokens=3" %%i in ('findstr "Session" fbsvc_check.lst.tmp') do ( @Rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1 ########### ] cls findstr /c:"%dbtest%" %fbslog%>%actlog% echo. echo Content of copy-of-%fbslog% related to actions: Correct following env. variables in it: set fbhome=C:\1INSTALL\FIREBIRD\fb30sS -- and run several times. You will be able to see following messages about comparing files using fc.exe: . . . ***** fbsvc_check.act.log ***** fbsvc_check.act.log ***** fbsvc_check.act.log ***** fbsvc_check.act.log etc. Is is unlikely that you will see message about no difference between estimated and actual output of trace - untill you UNCOMMENT line: @Rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1 ########### ] (and maybe you need to change number of seconds from '4' to +/- (1..2) here) Without knowledge about this 'feature' (that one need to wait several seconds after fbsvcmgr is stopped) it is very easy to get wrong results if analysis of trace log starts immediately after trace finish. And if trace log is huge I suppose that one need to wait this log to be flushed on disk much more - dozen seconds ? => It looks like very unpleasant "feature" that FBSVCMGR with action_trace_stop can return control to outer environment (batch or fbtest) without checking that OS really has finished writing of log. Consider following batch (be sure that you have standard utility for comparing text files - 'fc.exe' on Windows): === start of batch `fbsvc_check.bat` === cls set fbhome=C:\1INSTALL\FIREBIRD\fb30sS set fbscfg=%~n0.cfg.tmp del %fbscfg% 2>nul echo services>> %fbscfg% set estlog=%~n0.est.log set actlog=%~n0.act.log echo %dbtest% %dbbkup% >>%estlog% set str=%fbsrun% action_trace_start trc_cfg %fbscfg% 1^>%fbslog% 2^>^&1 ping -n 2 127.0.0.1>nul @Rem Do some actions which should be written into trace log: @echo --- BACKUP --- @echo --- RESTORE --- @echo --- STATISTICS of sys relations --- @echo --- STATISTICS of header --- @echo --- PROPERTIES: update FW --- @echo --- PROPERTIES: update BUFFERS number --- @echo --- PROPERTIES: update SWEEP interval --- @echo --- PROPERTIES: change SQL DIALECT --- @echo --- PROPERTIES: make database READ-ONLY --- @echo --- PROPERTIES: return database to READ-WRITE --- %fbsrun% action_trace_list 1>%fbslst% 2>&1 for /f "tokens=3" %%i in ('findstr "Session" %fbslst%') do ( @Rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1 ########### ] cls findstr /c:"%dbtest%" %fbslog%>%actlog% echo. echo Content of copy-of-%fbslog% related to actions: Correct following env. variables in it: set fbhome=C:\1INSTALL\FIREBIRD\fb30sS -- and run several times. You will be able to see following messages about comparing files using fc.exe: . . . ***** fbsvc_check.act.log ***** fbsvc_check.act.log ***** fbsvc_check.act.log ***** fbsvc_check.act.log etc. Is is unlikely that you will see message about no difference between estimated and actual output of trace - untill you UNCOMMENT line: @Rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1 ########### ] (and maybe you need to change number of seconds from '4' to +/- (1..2) here) Without knowledge about this 'feature' (that one need to wait several seconds after fbsvcmgr is stopped) it is very easy to get wrong results if analysis of trace log starts immediately after trace finish. And if trace log is huge I suppose that one need to wait this log to be flushed on disk much more - dozen seconds ? |
Commented by: @pavel-zotov I've encountered that issue about lost trainling part of FBSVCMGR also can be applied to FB 2.5.5. Furthermore, FBSVCMGR can 'loose' trailing part of its log even when delay between action_trace_stop and start of parsing its log is really big -- say, 20 (yes, TWENTY) seconds. What's more "wonderful" is that probability of this event (loosing of several last rows from log) also depends on... how VERBOSE is batch, i.e. how many messages are directed to console by ECHO commands (!!) May be it's hard to believe but batch that was shown above will produce MORE messages about mismatch between expected and actual trace content if we commented its "echo" commands. I've changed this batch (added setting "verbose_output" = 1 | 0 and also adjusted it to be run on both FB 2.5 and 3.0 ), and created auxiliary .bat that calls this 'main' one in infinite loop. Please take these two batches ('main' and 'outer' for loop) for running in your environment: 1) main batch, name = 'fbsvc_check.bat' set ping_delay=%1 set verbose_output=1 set fbhome=C:\MIX\firebird\fb25\bin set engine=30 set dbtest=%~dp0e%engine%.fdb set fbscfg=%~n0.cfg.tmp del %fbscfg% 2>nul if .%engine%.==.25. ( echo -TRUSTED_SVC SYSDBA %dbtest% %dbbkup% >>%estlog% echo %dbtest% %dbbkup% >>%estlog% set str=%fbsrun% action_trace_start trc_cfg %fbscfg% 1^>%fbslog% 2^>^&1 ping -n 2 127.0.0.1>nul @Rem Do some actions which should be written into trace log: if .%verbose_output%.==.1. @echo --- BACKUP --- if .%verbose_output%.==.1. @echo --- RESTORE --- if .%verbose_output%.==.1. @echo --- STATISTICS of sys relations --- if .%verbose_output%.==.1. @echo --- STATISTICS of header --- if .%verbose_output%.==.1. @echo --- PROPERTIES: update FW --- if .%verbose_output%.==.1. @echo --- PROPERTIES: update BUFFERS number --- if .%verbose_output%.==.1. @echo --- PROPERTIES: update SWEEP interval --- if .%verbose_output%.==.1. @echo --- PROPERTIES: change SQL DIALECT --- if .%verbose_output%.==.1. @echo --- PROPERTIES: make database READ-ONLY --- if .%verbose_output%.==.1. @echo --- PROPERTIES: return database to READ-WRITE --- %fbsrun% action_trace_list 1>%fbslst% 2>&1 if .%verbose_output%.==.1. ( for /f "tokens=3" %%i in ('findstr "Session" %fbslst%') do ( %fbsrun% action_trace_stop trc_id %%i 1>>%ownlog% if .!verbose_output!.==.1. ( if .%verbose_output%.==.1. ( if .%verbose_output%.==.1. (
) findstr /c:"%dbtest%" %fbslog%>%actlog% if .%verbose_output%.==.1. ( if .%verbose_output%.==.1. ( 2) auxiliary batch for infinite loop, name = 'fbsvc_loop.bat':@echo off
|
Modified by: @pavel-zotovAttachment: fbsvcmgr-do_NOT-waiting-for-its-log-will-be-completely-written-on-disk_-_batches-and-logs.zip [ 12790 ] |
Modified by: @dyemanovVersion: 2.5.4 [ 10585 ] |
Submitted by: @pavel-zotov
Attachments:
fbsvcmgr-do_NOT-waiting-for-its-log-will-be-completely-written-on-disk_-_batches-and-logs.zip
It looks like very unpleasant "feature" that FBSVCMGR with action_trace_stop can return control to outer environment (batch or fbtest) without checking that OS really has finished writing of log.
This effect can be watched at least on Windows 32-bit, I've checked FB build WI-V3.0.0.31948.
Consider following batch (be sure that you have standard utility for comparing text files - 'fc.exe' on Windows):
=== start of batch `fbsvc_check.bat` ===
@echo off
setlocal enabledelayedexpansion enableextensions
cls
set fbhome=C:\1INSTALL\FIREBIRD\fb30sS
set fbhost=localhost
set fbport=3333
set dbtest=C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb
set dbbkup=C:\FBTESTING\qa\fbt-repo\tmp\e30.fbk
set fbsrun=%fbhome%\fbsvcmgr %fbhost%/%fbport%:service_mgr user SYSDBA password masterkey
set fbscfg=%~n0.cfg.tmp
set fbslst=%~n0.lst.tmp
set fbslog=%~n0.trc.log
set ownlog=%~n0.own.log
del %fbscfg% 2>nul
del %fbslst% 2>nul
del %fbslog% 2>nul
del %ownlog% 2>nul
echo services>> %fbscfg%
echo {>> %fbscfg%
echo enabled = true>> %fbscfg%
echo log_services = true>> %fbscfg%
echo exclude_filter = "%%((List Trace Sessions)|(Start Trace Session))%%">> %fbscfg%
echo }>> %fbscfg%
set estlog=%~n0.est.log
del %estlog% 2>nul
set actlog=%~n0.act.log
del %actlog% 2>nul
echo %dbtest% %dbbkup% >>%estlog%
echo -REPLACE_DATABASE %dbbkup% %dbtest% >>%estlog%
echo %dbtest% -SYSTEM >>%estlog%
echo %dbtest% -HEADER >>%estlog%
echo %dbtest% -WRITE ASYNC >>%estlog%
echo %dbtest% -BUFFERS 3210 >>%estlog%
echo %dbtest% -HOUSEKEEPING 33333 >>%estlog%
echo %dbtest% -SQL_DIALECT 1 >>%estlog%
echo %dbtest% -MODE READ_ONLY >>%estlog%
echo %dbtest% -MODE READ_WRITE >>%estlog%
set str=%fbsrun% action_trace_start trc_cfg %fbscfg% 1^>%fbslog% 2^>^&1
echo Starting trace session using FBSVCMGR.
echo Command: %str%
start /min cmd /c !str!
ping -n 2 127.0.0.1>nul
@Rem Do some actions which should be written into trace log:
@echo --- BACKUP ---
%fbsrun% action_backup dbname %dbtest% bkp_file %dbbkup%
@echo --- RESTORE ---
%fbsrun% action_restore bkp_file %dbbkup% dbname %dbtest% res_replace
@echo --- STATISTICS of sys relations ---
%fbsrun% action_db_stats dbname %dbtest% sts_sys_relations 1>nul
@echo --- STATISTICS of header ---
%fbsrun% action_db_stats dbname %dbtest% sts_hdr_pages 1>nul
@echo --- PROPERTIES: update FW ---
%fbsrun% action_properties dbname %dbtest% prp_write_mode prp_wm_async
@echo --- PROPERTIES: update BUFFERS number ---
%fbsrun% action_properties dbname %dbtest% prp_page_buffers 3210
@echo --- PROPERTIES: update SWEEP interval ---
%fbsrun% action_properties dbname %dbtest% prp_sweep_interval 33333
@echo --- PROPERTIES: change SQL DIALECT ---
%fbsrun% action_properties dbname %dbtest% prp_set_sql_dialect 1
@echo --- PROPERTIES: make database READ-ONLY ---
%fbsrun% action_properties dbname %dbtest% prp_access_mode prp_am_readonly
@echo --- PROPERTIES: return database to READ-WRITE ---
%fbsrun% action_properties dbname %dbtest% prp_access_mode prp_am_readwrite
%fbsrun% action_trace_list 1>%fbslst% 2>&1
for /f "tokens=3" %%i in ('findstr "Session" %fbslst%') do (
echo %time% %~nx0: request to stop trace session with id = %%i 1>>%ownlog%
%fbsrun% action_trace_stop trc_id %%i 1>>%ownlog%
echo %time% %~nx0: control from FBSVCMGR returned to this batch.>>%ownlog%
copy %fbslog% copy-of-%fbslog% 1>nul
echo %time% %~nx0: copy of trace log has been created.>>%ownlog%
)
@Rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1 ########### ]
cls
echo Estimated to be seen in trace log (see %estlog%^):
echo --------------------------------------------------------------------
type %estlog%
echo --------------------------------------------------------------------
findstr /c:"%dbtest%" %fbslog%>%actlog%
echo.
echo Actual content of trace log (%fbslog%^) related to actions:
echo --------------------------------------------------------------------
type %actlog%
echo --------------------------------------------------------------------
echo.
echo Difference between estimated and actual content, w/o leading or trailing spaces and tabs:
echo -----------------------------------------------------------------------------------------
fc.exe /c /n /w %actlog% %estlog%
@Rem echo %errorlevel%
echo Content of copy-of-%fbslog% related to actions:
findstr /c:"%dbtest%" copy-of-%fbslog%
=== end of batch `fbsvc_check.bat` ===
Correct following env. variables in it:
set fbhome=C:\1INSTALL\FIREBIRD\fb30sS
set fbhost=localhost
set fbport=3333
set dbtest=C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb
set dbbkup=C:\FBTESTING\qa\fbt-repo\tmp\e30.fbk
-- and run several times.
You will be able to see following messages about comparing files using fc.exe:
. . .
Comparing files fbsvc_check.act.log and FBSVC_CHECK.EST.LOG
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
9: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_ONLY
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
7: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -HOUSEKEEPING 33333
8: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -SQL_DIALECT 1
9: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_ONLY
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
. . .
***** fbsvc_check.act.log
***** FBSVC_CHECK.EST.LOG
8: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -SQL_DIALECT 1
9: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_ONLY
10: C:\FBTESTING\qa\fbt-repo\tmp\e30.fdb -MODE READ_WRITE
*****
etc.
Is is unlikely that you will see message about no difference between estimated and actual output of trace - untill you UNCOMMENT line:
@Rem ping -n 4 127.0.0.1>nul ----------------------------- [ ########### 1 ########### ]
(and maybe you need to change number of seconds from '4' to +/- (1..2) here)
Without knowledge about this 'feature' (that one need to wait several seconds after fbsvcmgr is stopped) it is very easy to get wrong results if analysis of trace log starts immediately after trace finish. And if trace log is huge I suppose that one need to wait this log to be flushed on disk much more - dozen seconds ?
Commits: FirebirdSQL/fbt-repository@9a8fa4c
The text was updated successfully, but these errors were encountered: