Issue Details (XML | Word | Printable)

Key: CORE-3769
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Minor Minor
Assignee: Alexander Peshkov
Reporter: Pavel Zotov
Votes: 0
Watchers: 3
Operations

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

The message `Unknown tag (4) in isc_svc_query() results` appears when fbtracemgr is interrupted by Ctrl-C

Created: 21/Feb/12 06:40 PM   Updated: 23/Apr/13 01:42 PM
Component/s: SVCMGR, TRACEMGR
Affects Version/s: 2.5.0, 2.5.1
Fix Version/s: 2.5.2, 3.0 Alpha 1

Time Tracking:
Not Specified

Planning Status: Unspecified


 Description  « Hide
Under some conditions fbtracemgr can output the following message when interrupt by Ctrl-C:
Unknown tag (4) in isc_svc_query() results

In particular I got this message when pressed Ctrl-C after tracing IBE for select count(*) from some_table.
Details (in russian): http://www.sql.ru/forum/actualutils.aspx?action=gotomsg&tid=838190&msg=12132939

 All   Comments   Work Log   Change History   Version Control   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Alexander Peshkov added a comment - 22/Feb/12 05:24 AM
It's not good idea to add links to national forums from interantional tracker. Please provide reproducible test case here, preferably using only native firebird tools.

Alexander Peshkov added a comment - 27/Mar/12 11:51 AM
Pavel, will test case be provided or should I close as 'cannot reproduce'?

Pavel Zotov added a comment - 27/Mar/12 01:42 PM
Alex, just now I have encountered this problem again, on our production.
I can`t provide 100% test case at this time so you can close this ticket if needed.
But if I could reproduce I will put testcase here.


Dmitry Yemanov added a comment - 27/Mar/12 02:12 PM
Alex, is the test case really needed? As far as I see, our utilities don't check for isc_info_data_not_ready being returned from isc_svc_query(). The example of how it could be handled can be found in GBAK. What other info is needed?

Pavel Zotov added a comment - 27/Mar/12 02:17 PM - edited
I got it!

create the following script named 'ibe.sql':
--- begin of script ---
set transaction read committed record_version no wait;
select RDB$RELATION_NAME from RDB$RELATIONS
where (RDB$RELATION_NAME = 'MON$ATTACHMENTS') and
(RDB$VIEW_BLR is NULL);

commit;
connect 192.168.0.60:/var/db/firebird/test/test.fdb user sysdba password 'qp26vtz1';
--- end of script ---

Then run isql utility in some folder (in my case: /var/db/firebird/test) and do these commands in it:
SQL> create database 'test.fdb'; commit;
SQL> quit;

Then connect from windows workstation to this database - let this session have name #1:

session #1
---------------
C:\MIX\firebird\fb25\bin>C:\MIX\firebird\fb25\bin\isql.exe 192.168.0.60:/var/db/firebird/test/test.fdb -n
Database: 192.168.0.60:/var/db/firebird/test/test.fdb
SQL> commit;

session #2 (PUTTy console):
---------------
supertee -n trc.txt fbtracemgr -sta -c zaudit.conf -se service_mgr

session #1
----------------

SQL> in ibe.sql;

RDB$RELATION_NAME
===============================================================================
MON$ATTACHMENTS -- And this is "THE END". No further activity, all databases are hangs.

Trace console:

-------- start of trace console -----
Trace session ID 8 started
2012-03-27T19:35:33.8090 (5151:0x7fb3f1b6c648) TRACE_INIT
        SESSION_8


2012-03-27T19:35:33.8100 (5151:0x7fb3f1b6c648) START_TRANSACTION
        /u02/db/firebird/test/test.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:192.168.43.96)
        C:\MIX\firebird\fb25\bin\isql.exe:1764
                (TRA_91, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

2012-03-27T19:35:33.8140 (5151:0x7fb3f1b6c648) EXECUTE_STATEMENT_START
        /u02/db/firebird/test/test.fdb (ATT_4, SYSDBA:NONE, NONE, TCPv4:192.168.43.96)
        C:\MIX\firebird\fb25\bin\isql.exe:1764
                (TRA_91, READ_COMMITTED | REC_VERSION | NOWAIT | READ_WRITE)

Statement 35:
-------------------------------------------------------------------------------
select RDB$RELATION_NAME from RDB$RELATIONS
where (RDB$RELATION_NAME = 'MON$ATTACHMENTS') and
(RDB$VIEW_BLR is NULL)

2012-03-27T19:35:33.8140 (5151:0x7fb3f1b6c648) EXECUTE_STATEMENT_FINISH
-------- end of trace console -----

Trace config file ('zaudit.conf'):
----- start of trace config ----
bash-4.1$ cat /opt/firebird/zaudit.conf
<database (%[\\/](r`eplcfg|ttt%|zzz%|k`untsevomain|kmain2012%|test%).fdb)|(k`ntsevomain|kmain4trace)>
  enabled true
  log_filename /var/db/firebird/trace/zaudit.log
  log_connections true
  log_transactions true

  log_statement_start true
  log_statement_finish true

  #log_trigger_start true
  #log_trigger_finish true
  #log_procedure_start true
  #log_procedure_finish true
  #print_plan true
  print_perf true
  max_sql_length 16384
  time_threshold 0
  max_log_size 10
</database>
----- end of trace config ----

bash-4.1$ lsof /var/db/firebird/test/test.fdb
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
fb_inet_s 5151 firebird 9u REG 8,145 827392 10485906 /u02/db/firebird/test/test.fdb


top -p 5151

top - 19:45:31 up 12 days, 17:13, 5 users, load average: 46.86, 37.16, 23.01
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 12.3%us, 2.9%sy, 0.0%ni, 81.8%id, 2.8%wa, 0.0%hi, 0.2%si, 0.0%st
Mem: 37139904k total, 27606200k used, 9533704k free, 109928k buffers
Swap: 36863992k total, 41876k used, 36822116k free, 22891200k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 5151 firebird 20 0 236m 12m 7140 S 14.0 0.0 3:10.49 fb_inet_server


top -p $(pgrep fbtracemgr)

top - 19:47:04 up 12 days, 17:14, 5 users, load average: 47.15, 39.89, 25.36
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
Cpu(s): 12.3%us, 3.0%sy, 0.0%ni, 81.8%id, 2.8%wa, 0.0%hi, 0.2%si, 0.0%st
Mem: 37139904k total, 27603292k used, 9536612k free, 109988k buffers
Swap: 36863992k total, 41876k used, 36822116k free, 22891200k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 5342 firebird 20 0 154m 8448 6280 S 8.0 0.0 2:00.40 fbtracemgr



session # 3 (just for illustration: try to create another one database):
----------------
bash-4.1$ isql
Use CONNECT or CREATE DATABASE to specify a database
SQL> create database 'test2.fdb'; commit;
--- hangs infinite time!
^Z
[1]+ Stopped isql

PS. All these processes (fb_inet, fbtracemgr) can be cancelled only via kill -9, rather than kill -15.

Alexander Peshkov added a comment - 28/Mar/12 05:50 AM
Dmitry, adding code to process data_not_ready condition is very simple to do. But I want to know conditions under which it happens (looks like it may happen only during services manager shutdown). And the worst detail - it happens sometimes, i.e. looks like we have a kind of races here. Before hiding them at client side I want to understand how do they happen and can it be dangerous or not.

Alexander Peshkov added a comment - 28/Mar/12 06:32 AM
Pavel, sorry - I've tried to reproduce your hang, but no luck. The only difefrence is that instead of remote windows workstation (do not have one) I've used one more linux tty. Do not think that client makes much difference here. Everything works fine for me.

PS. How is it related with initial problem?

Dmitry Yemanov added a comment - 28/Mar/12 06:39 AM
As a wild guess - could it be somehow related to CORE-3770? I mean that Alex has it fixed now while Pavel has not, and this fact could affect the ability to reproduce the issue being discussed.

Alexander Peshkov added a comment - 28/Mar/12 07:22 AM
No.
I've emulated old behavior, but anyway no hang.

Alexander Peshkov added a comment - 28/Mar/12 07:30 AM
Pavel, may be you have some special firebird.conf settings?

Pavel Zotov added a comment - 28/Mar/12 08:29 AM
I've tried this on:
SQL> show version;
ISQL Version: LI-V2.5.2.26436 Firebird 2.5
Server version:
Firebird/linux AMD64 (access method), version "LI-V2.5.2.26436 Firebird 2.5"
on disk structure version 11.2

There were only few changes in firebird.conf, namely:

# set 05.03.2012 1630, after change mode to SC:
DefaultDbCachePages = 768

# to be increased after 12.03.2012 (check connects count and memo consumption before doing that!)
#TempCacheLimit = 16777216 // not sure that it was really done

# 28-11-2011 1747
MaxUnflushedWrites = -1

# 28-11-2011 1747
MaxUnflushedWriteTime = -1

# enabled 05-oct-2010 19:03 due to errors in firebird.log
BugcheckAbort = 1

# 16.11.2010 15:15:
ConnectionTimeout = 90

# increased 12.03.2012:
LockMemSize = 4194304

#LockHashSlots =3169
#LockHashSlots = 10091
# 12.03.2012 1755
# increase hashslots due to big average hash length = 10 (min/avg/max = 2/10/22 - looked at fb_lock_print log header blobk)
LockHashSlots = 25013


Alexander Peshkov added a comment - 04/Jun/12 04:55 PM
Have no testcase to check, but this fix should help