Very slow close of statement [execute SP] [CORE3982]

[firebird-automations]

Submitted by: @ibprovider

Server Version :2.5.3.26543 [Windows, x64, SuperClassic]
Client Version :2.5.3.26543
Database ODS :11.2
Database Dialect:3

---------- [Test stored procedure]
CREATE PROCEDURE SP_PAUSE_FETCH(N INTEGER, PAUSE INTEGER)
RETURNS (ID INTEGER,DUMMY VARCHAR(32000))
AS
DECLARE VARIABLE P INTEGER;
DECLARE VARIABLE S INTEGER;
BEGIN
ID=0;

DUMMY='';
P=0;
WHILE(P<32000)DO
BEGIN
DUMMY=DUMMY||'A';
P=P+1;
END

S=0;
WHILE(S=0)DO
BEGIN
P=0;
WHILE(P<PAUSE) DO P=P+1;

IF(ID<N)THEN
BEGIN
ID=ID+1;
SUSPEND;
END
ELSE
BEGIN
S=1;
END
END
END
---------- [/Test stored procedure]

Scenario of API call

1. begin transaction
2. prepare and execute "select ID,DUMMY from SP_PAUSE_FETCH(1000,10000000)"
3. fetch one row
4. close statement <---- very slow operation.

[firebird-automations]

Commented by: @dyemanov

What does the "very slow" mean? One second? More?

[firebird-automations]

Commented by: @ibprovider

Hm. Sorry.

Duration of close operation: 00:01:25.4138854.

[firebird-automations]

Commented by: @AlexPeshkoff

On dev build this caused assertion.

Core was generated by `./isql -user sysdba -pas localhost:employee'.
Program terminated with signal 6, Aborted.
#⁠0 0x00007f94b27b38b5 in raise () from /lib64/libc.so.6
(gdb) bt
#⁠0 0x00007f94b27b38b5 in raise () from /lib64/libc.so.6
#⁠1 0x00007f94b27b4ce0 in abort () from /lib64/libc.so.6
#⁠2 0x00007f94b3f2c527 in REM_free_statement (user_status=0x689780, stmt_handle=0x7f94b4793630, option=2) at ../src/remote/interface.cpp:1959
#⁠3 0x00007f94b3c58c4c in isc_dsql_free_statement (user_status=0x689780, stmt_handle=0x68bb08, option=2) at ../src/jrd/why.cpp:3349
#⁠4 0x0000000000415072 in do_isql () at ../temp/std/isql/isql.cpp:5120
#⁠5 0x000000000040caaa in ISQL_main (argc=6, argv=0x7fff4c018238) at ../temp/std/isql/isql.cpp:991
#⁠6 0x000000000040c7e1 in main (argc=6, argv=0x7fff4c018238) at ../temp/std/isql/isql.cpp:879
(gdb) f 2
#⁠2 0x00007f94b3f2c527 in REM_free_statement (user_status=0x689780, stmt_handle=0x7f94b4793630, option=2) at ../src/remote/interface.cpp:1959
1959 fb_assert(statement->haveException() == 0);

WIth local connection no such problem, IMHO the reason of delay in release build is remote protocol.

[firebird-automations]

Commented by: @hvlad

Remote server send batch of records (even if application made just one fetch call) and evaluates next batch.

So, it is expected that next operation with statement (close) will wait at least one internal fetch to complete.
More, any API call on this attachment will wait, i guess.

There should be no such wait if local protocol is used (XNET).

[firebird-automations]

Commented by: @dyemanov

Also worth checking as:
select ID,DUMMY from SP_PAUSE_FETCH(1000,10000000) FOR UPDATE
to turn the batching off

[firebird-automations]

Commented by: @ibprovider

The problem with assert still exists.

Server Version :2.5.4.26822 (SuperClassic x64, DEBUG build)
Client Version :2.5.4.26822 (x64, DEBUG build)

[Stack]
msvcr120d.dll!abort() Unknown
> gds32.dll!REM_free_statement(__int64 * user_status=0x00000000027aed90, Rsr * * stmt_handle=0x0000000000378270, unsigned short option=2) Line 1958 C++
gds32.dll!isc_dsql_free_statement(__int64 * user_status=0x00000000027aed90, unsigned int * stmt_handle=0x0000000002f6d7d0, unsigned short option=2) Line 3348 C++
_IBProvider_v3_vc12xp_w64_i.dll!isc_base::t_isc_connection::gc_task__drop_old_stmt(ibp::t_ibp_task_std__holder_signals<ibp::t_ibp_task_std__holderibp::t\_ibp\_task\_manager\_connector\ > * task_signals=0x000000006437e812, long stmt_cache_time_limit=1225326656, long stmt_cache_size_limit=0) Line 1089 C++
_IBProvider_v3_vc12xp_w64_i.dll!isc_base::t_isc_connection::helper__deinitialize() Line 423 C++
_IBProvider_v3_vc12xp_w64_i.dll!isc_base::t_isc_connection::deinitialize() Line 397 C++
_IBProvider_v3_vc12xp_w64_i.dll!ibp::TIBPDataSource::Uninitialize() Line 170 C++
oledb32.dll!CDBInitialize::Uninitialize(void) Unknown
oledb32.dll!CDPO::UnlockedDCMUninit(void) Unknown
oledb32.dll!CDPO::UnInitWithPooledSession(void) Unknown
oledb32.dll!CDPO::Uninitialize(void) Unknown
ibp_oledb_test_vc11_x64_Release_xp.exe!oledb_lib::t_db_data_source::uninitialize() Line 244 C++
ibp_oledb_test_vc11_x64_Release_xp.exe!ibp_tso::TIBP_TSO_RowsetAsynch003__AbortActiveLoader::run(ibp_tso::TTSO_TestContext * ctx=0x0000000001d7e6e0) Line 488 C++
ibp_oledb_test_vc11_x64_Release_xp.exe!ibp_tso::TTSO_TestRunnerMT::thread_worker_impl() Line 608 C++
ibp_oledb_test_vc11_x64_Release_xp.exe!structure::t_basic_thread_controller<structure::t_basic_smem_objstructure::t\_multi\_thread\_traits,ibp\_tso::TTSO\_MemoryAllocator\ >::thread_member() Line 116 C++
ibp_oledb_test_vc11_x64_Release_xp.exe!structure::t_basic_thread_controller__win32<structure::t_basic_smem_objstructure::t\_multi\_thread\_traits,ibp\_tso::TTSO\_MemoryAllocator\ >::ThreadEntryPoint(void * lpParam=0x0000000000000000) Line 95 C++

[Locals]
- statement 0x0000000000350500 {rsr_next=0x0000000000000000 <NULL> rsr_rdb=0x0000000000370110 {rdb_id=0 rdb_flags=...} ...} Rsr *
Firebird::GlobalStorage {...} Firebird::GlobalStorage
+ TypedHandle<99> {blockType=rem_type_rsr (99) } TypedHandle<99>
+ rsr_next 0x0000000000000000 <NULL> Rsr *
+ rsr_rdb 0x0000000000370110 {rdb_id=0 rdb_flags=0 rdb_handle=0 ...} Rdb *
+ rsr_rtr 0x0000000000000000 <NULL> Rtr *
rsr_handle 2 unsigned int
+ rsr_bind_format 0x0000000000000000 <NULL> rem_fmt *
+ rsr_select_format 0x00000000003405e8 {fmt_length=32010 fmt_net_length=32016 fmt_count=4 ...} rem_fmt *
+ rsr_user_select_format 0x0000000000349330 {fmt_length=32010 fmt_net_length=32016 fmt_count=4 ...} rem_fmt *
+ rsr_format 0x00000000003405e8 {fmt_length=32010 fmt_net_length=32016 fmt_count=4 ...} rem_fmt *
+ rsr_message 0x0000000000340630 {msg_next=0x0000000000340630 {msg_next=0x0000000000340630 {msg_next=0x0000000000340630 {...} ...} ...} ...} RMessage *
+ rsr_buffer 0x0000000000340630 {msg_next=0x0000000000340630 {msg_next=0x0000000000340630 {msg_next=0x0000000000340630 {...} ...} ...} ...} RMessage *
- rsr_status 0x0000000000354710 {m_status_vector=0x0000000000354710 {1, 335544794, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, ...} ...} Firebird::StatusHolder *
+ m_status_vector 0x0000000000354710 {1, >>>>>> 335544794 (cancelled) <<<<<<<<<<<< , 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0} __int64[20]
m_raised false bool
rsr_id 2 unsigned short
+ rsr_flags {m_flags=80 } RFlags<unsigned short>
rsr_fmt_length 32010 unsigned short
rsr_rows_pending 0 unsigned long
rsr_msgs_waiting 0 unsigned short
rsr_reorder_level 0 unsigned short
rsr_batch_count 0 unsigned short

-----------
I think, need remove or correct this assert.