Issue Details (XML | Word | Printable)

Key: CORE-3982
Type: Bug Bug
Status: Open Open
Priority: Major Major
Assignee: Unassigned
Reporter: Kovalenko Dmitry
Votes: 0
Watchers: 7
Operations

If you were logged in you would be able to see more operations.
Firebird Core

Very slow close of statement [execute SP]

Created: 15/Nov/12 07:01 AM   Updated: 04/Jan/15 07:18 AM
Component/s: API / Client Library, Engine
Affects Version/s: 2.5.2
Fix Version/s: None

Environment: Win7 x64, i7-Q2670QM.


 Description  « Hide
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.

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Dmitry Yemanov added a comment - 15/Nov/12 07:14 AM
What does the "very slow" mean? One second? More?

Kovalenko Dmitry added a comment - 15/Nov/12 07:23 AM
Hm. Sorry.

Duration of close operation: 00:01:25.4138854.

Alexander Peshkov added a comment - 15/Nov/12 08:24 AM
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.

Vlad Khorsun added a comment - 15/Nov/12 08:53 AM
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).

Dmitry Yemanov added a comment - 15/Nov/12 09:04 AM
Also worth checking as:
select ID,DUMMY from SP_PAUSE_FETCH(1000,10000000) FOR UPDATE
to turn the batching off

Kovalenko Dmitry added a comment - 04/Jan/15 07:18 AM
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__holder<ibp::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_obj<structure::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_obj<structure::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.