Ask Reuben

FGLSQLDEBUG

How can I see what SQL statement was sent to the database? 

How can I see the values passed as parameters, or received as results to/from the database? 

How can I see the differences between the SQL in my code and the SQL executed on the database? 

How can I see how long an SQL statement took to execute on the database?

How can I see the native error code for an SQL statement on a database?

I have seen a number of support cases recently where the correct tool to use in identifying the cause of an issue was to use the FGLSQLDEBUG environment variable.

I find using the FGLSQLDEBUG valuable in telling me what the SQL statement sent to the database is, what the parameters sent were, and what the results sent back were.  Too often I see developers focusing on the 4gl code in thinking what the SQL statement executed is, when particularly with databases other than Informix, the ODI layer is going to transform the SQL syntax from the Informix syntax to the appropriate syntax for that database.

FGLSQLDEBUG is an environment variable you can set before the program is run and as per the documentation you can set different values to get more information back.  I tend to find I set it to the maximum 3 and then work with the volumes of data returned.  Other strategies are to set it to -1 to find where the error is, and then dive deeper from there once you see where an error is occurring.  Alternatively you can use the fgl_sqldebug function in your code to change the value in the middle of a program.

One strategy for debugging is to add the following library functions

FUNCTION fgl_sqldebug_on()
    CALL fgl_sqldebug(3)
END FUNCTION

FUNCTION fgl_sqldebug_off()
    CALL fgl_sqldebug(0)
END FUNCTION

… and then when using the debugger, either at the command line, or the Graphical Debugger in Genero Studio , you can use the call command inside the debugger to enable and disable FGLSQLDEBUG as you are debugging i.e call fgl_sqldebug_on() and call _fgl_sqldebug_off().

When examining FGLSQLDEBUG output I can see the following …

  • the SQL statement from the 4gl code
  • the SQL statement as it is passed to the database after being transformed by the ODI layer
  • any parameters passed to the SQL statement
  • the results of the SQL statement
  • the native error code and description
  • the 4gl error code
  • the line number in the 4gl code
  • the execution time

To illustrate at the end of this article I have a complete 4gl program that you can run.  It uses the SQLite database so you can see some examples of the ODI layer at work changing the SQL statement and parameters.  Next I will show some output from this program when FGLSQLDEBUG=3 and point out some things to note.


SQL: CONNECT TO ":memory:+driver='dbmsqt'"
 | 4gl source      : askreuben83.4gl line=14
 | loading driver  : [/Applications/fourjs/fgl/3.20.11/dbdrivers/dbmsqt]
 | db driver type  : sqt
 | sqt.c:00346(3)  : Connection parameters for ':memory:+driver='dbmsqt'':
 | sqt.c:00347(3)  :  Database      = ':memory:'
 | sqt.c:00321(1)  :  SQLite version   = 3.28.0
 | sqt.c:00324(1)  :  Numeric version  = 328
 | ../ODI_common.h:00501(3)  : ODI_Connect: ifxemul = 1
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | Execution time  :   0 00:00:00.00412

The first line of each section is the 4gl SQL code.  This line does not being with a |.

I’ll explain this snippet in more detail than I will the other snippets.

SQL: CONNECT TO ":memory:+driver='dbmsqt'".

This first line is showing the SQL instruction from the 4gl code, in this case the connection to the database.

We can see in each section…

  • the line number in the 4gl code that it relates to: 4gl source : askreuben83.4gl line=14
  • the database driver loaded and location: loading driver : [/Applications/fourjs/fgl/3.20.11/dbdrivers/dbmsqt] ...| db driver type : sqt
  • the connection parameters which in this case include the name of the database and the version of the database:
    sqt.c:00346(3) : Connection parameters for ':memory:+driver='dbmsqt'':
    sqt.c:00347(3) : Database = ':memory:'
    sqt.c:00321(1) : SQLite version = 3.28.0
    sqt.c:00324(1) : Numeric version = 328
  • Is Informix emulation enabled ?: ../ODI_common.h:00501(3) : ODI_Connect: ifxemul = 1
  • The error code returned (0 is good): sqlcode : 0
  • How long the execution took: Execution time : 0 00:00:00.00412

Normally when looking at this output, it may tell us errors in your configuration which mean you are not pointing to the database or database drivers you think you are

When used with SQL Server database, this connection output has appeared a few times in support cases …

snc.c:00526(3) : ODBC Driver = 'msodbcsql17.dll'
...src\sqldriver\ODI_common_msv.h:00071(1) : Server version = 15.0.2070.41
...src\sqldriver\ODI_common_msv.h:00072(1) : DB Compat version= 100
...src\sqldriver\ODI_common_msv.h:00083(1) : Normalized vers. = 1000
...src\sqldriver\ODI_common_msv.h:00091(1) : Unsupported SQL Server version

… and what this output has pointed us at is that the customers have altered the compatibility of the SQL Server database (https://docs.microsoft.com/en-us/sql/relational-databases/databases/view-or-change-the-compatibility-level-of-a-database?view=sql-server-ver15) to be that of a 2008 database.  The DB Compat version = 100 corresponds to SQL Server 2008 (https://docs.microsoft.com/en-us/sql/t-sql/statements/alter-database-transact-sql-compatibility-level?view=sql-server-ver15#supported-dbcompats)


SQL: CREATE TABLE foo (id SERIAL,str CHAR (40),dmy DATE,num DECIMAL (11, 2))
 | 4gl source      : askreuben83.4gl line=17
 | ../ODI_common.h:00795(3)  : adaptStatement: stmt type = 0
 | ../ODI_common.h:00800(3)  : adaptStatement: ifxemul = 1
 | sqt.c:00868(3)  : Nat stmt1 = create table foo (id integer primary key autoincrement ,str char(40) collate rtrim,dmy date,num decimal(11,2))
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | Execution time  :   0 00:00:00.00056

What I want to point out with this CREATE TABLE is note how the syntax changes from Informix syntax to the appropriate syntax for the database, in this case the statement …

CREATE TABLE foo (id SERIAL,str CHAR (40),dmy DATE,num DECIMAL (11, 2))

… becomes in SQLite syntax…

create table foo (id integer primary key autoincrement ,str char(40) collate rtrim,dmy date,num decimal(11,2)).

The following mappings have taken place …

  • SERIAL is mapped to integer primary key autoincrement
  • CHAR(40) is mapped to char(40) collate rtrim

You will see different mappings depending upon the database in use and the emulation rules you have adopted.


SQL: INSERT INTO foo (str,dmy,num) VALUES ('AAA',today,12.34)
 | 4gl source      : askreuben83.4gl line=25
 | ../ODI_common.h:00795(3)  : adaptStatement: stmt type = 2
 | ../ODI_common.h:00800(3)  : adaptStatement: ifxemul = 1
 | sqt.c:00868(3)  : Nat stmt1 = insert into foo (str,dmy,num) VALUES ('AAA',date('now'),12.34)
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | Execution time  :   0 00:00:00.00021

Similarly in the INSERT, again Informix syntax being changed to the appropriate syntax for the database.

INSERT INTO foo (str,dmy,num) VALUES ('AAA',today,12.34)

… becomes …

insert into foo (str,dmy,num) VALUES ('AAA',date('now'),12.34).

In this example, the Informix today is mapped to the SQLite date ('now')

Not illustrated in this example but sometimes you will also see a SELECT added after the INSERT by the ODI layer. Typically this occurs when there is a SERIAL column and the SELECT is fetching the value of the SERIAL column. This will depend upon the database and the emulation strategy adopted.


SQL: SELECT COUNT(*) FROM foo
 | 4gl source      : askreuben83.4gl line=33
 | ../ODI_common.h:00795(3)  : adaptStatement: stmt type = 1
 | ../ODI_common.h:00800(3)  : adaptStatement: ifxemul = 1
 | sqt.c:00868(3)  : Nat stmt1 = select COUNT(*) from   foo
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | into: 1
 |  t:                       INTEGER f:04 v:"2"
 | Execution time  :   0 00:00:00.00018

In this static SQL syntax example, we can see that the SQL statement has not needed to be altered from its Informix syntax to the SQLite syntax, other than the INTO being removed.  The other place I am looking is where the results are gathered.  With…

into: 1
t: INTEGER f:04 v:"2"

… we can see the number of values returned (1), the database type (INTEGER), and the actual value (“2”).


SQL: DECLARE
 | 4gl source      : askreuben83.4gl line=38
 | ../ODI_common.h:00795(3)  : adaptStatement: stmt type = 1
 | ../ODI_common.h:00800(3)  : adaptStatement: ifxemul = 1
 | sqt.c:00868(3)  : Nat stmt1 = select str, dmy, num from   foo where id = ? 
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | sql cursor      : ident='cu0' (fglname='fetch_curs',module='askreuben83')
 |   fgl stmt      : SELECT str, dmy, num FROM foo WHERE id = ? 
 |   sql stmt      : SELECT str, dmy, num FROM foo WHERE id = ? 
 |   scroll cursor : 0
 |   with hold     : 0
 | Execution time  :   0 00:00:00.00017

With a cursor, the declare, prepare, open, fetch are all statements that occur on the database.  So in the FGLSQLDEBUG output you should see an entry for each one.  Again the key thing to look for is any mapping of the Informix syntax to the target database syntax.

fgl stmt : SELECT str, dmy, num FROM foo WHERE id = ?
sql stmt : SELECT str, dmy, num FROM foo WHERE id = ?

In this case there is not any.  Also note the ? as these are placeholders for the input parameters to the query.


SQL: OPEN
 | 4gl source      : askreuben83.4gl line=41
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | sql cursor      : ident='cu0' (fglname='fetch_curs',module='askreuben83')
 |   fgl stmt      : SELECT str, dmy, num FROM foo WHERE id = ? 
 |   sql stmt      : SELECT str, dmy, num FROM foo WHERE id = ? 
 | using(tmp): 1
 |  t:                       INTEGER f:01 v:"1"
 | Execution time  :   0 00:00:00.00006

The key thing with the OPEN statement is to note the parameter(s) that are being passed into the query, the number of them, the datatypes, and the values.

using(tmp): 1
t: INTEGER f:01 v:"1" 


SQL: FETCH NEXT
 | 4gl source      : askreuben83.4gl line=42
 | sqlcode         : 0
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | sql cursor      : ident='cu0' (fglname='fetch_curs',module='askreuben83')
 |   fgl stmt      : SELECT str, dmy, num FROM foo WHERE id = ? 
 |   sql stmt      : SELECT str, dmy, num FROM foo WHERE id = ? 
 | into(tmp): 3
 |  t:                        STRING f:04 v:"AAA"
 |  t:                          DATE f:04 v:"09/06/2021"
 |  t:                 DECIMAL(11,2) f:04 v:"12.34"
 | Execution time  :   0 00:00:00.00014

When the FETCH occurs, again we can see the number of fields in the result set, the datatype and the values.

into(tmp): 3
t: STRING f:04 v:"AAA"
t: DATE f:04 v:"09/06/2021"
t: DECIMAL(11,2) f:04 v:"12.34"


SQL: SELECT COUNT(*) FROM foo2
 | 4gl source      : askreuben83.4gl line=47
 | ../ODI_common.h:00795(3)  : adaptStatement: stmt type = 1
 | ../ODI_common.h:00800(3)  : adaptStatement: ifxemul = 1
 | sqt.c:00868(3)  : Nat stmt1 = select COUNT(*) from   foo2
 | sqt.c:00292(3)  : Diagnostic info:
 | sqt.c:00293(3)  :   SQL code : 1
 | sqt.c:00294(3)  :   Message  : no such table: foo2
 | sqlcode         : -6372
 |   sqlstate      : HY000
 |   sqlerrd2      : -1
 |   sql message   : no such table: foo2
 |   sql msg param : 
 | curr driver     : ident='dbmsqt'
 | curr connection : ident=':memory:+driver='dbmsqt'' (dbspec=[:memory:+driver='dbmsqt'])
 | Execution time  :   0 00:00:00.00014

Finally this last SQL statement which is a deliberate error.  Note how the error from the database (1)…

sqt.c:00293(3) : SQL code : 1
sqt.c:00294(3) : Message : no such table: foo2

… is mapped to the 4gl and Informix error (-6372).   (https://4js.com/online_documentation/fjs-fgl-manual-html/#fgl-topics/r_fgl_errors_001.html#r_fgl_errors_001__error-6372).

sqlcode : -6372
sqlstate : HY000
sqlerrd2 : -1
sql message : no such table: foo2
sql msg param :

This shows how the SQLCA diagnostic record is populated.

You may also find this page of the documentation handy when mapping errors. https://4js.com/online_documentation/fjs-fgl-manual-html/#fgl-topics/c_fgl_sql_programming_error_ident.html .


So hopefully you can see the value of the FGLSQLDEBUG output in telling you what the SQL was in the 4gl code and what the actual SQL executed on the database is.

I’ll finish by pointing out a tool Seb put up on our Github repository.  The repository tool_fglsqldebug contains a Genero program that takes as input the FGLSQLDEBUG output, parses it and displays it in a Genero application.  Below are some screenshots from that application on some of the output illustrated above.

You may find it preferable to filter FGLSQLDEBUG output through that.  You can also take that source and modify it to suit your requirements.




(Below is the code used to generate the FGLSQLDEBUG output in the article.  It runs against a SQLite database in memory as illustrated in this article.)


MAIN
DEFINE foo_count INTEGER

DEFINE sql STRING

DEFINE id INTEGER
DEFINE rec RECORD
    str STRING,
    dmy DATE,
    num DECIMAL(11,2)
END RECORD

    -- Database connection
    CONNECT TO ":memory:+driver='dbmsqt'"

    -- Create a table
    CREATE TABLE foo(
        id SERIAL,
        str CHAR(40),
        dmy DATE,
        num DECIMAL(11,2)
        )

    -- Insert rows with serial
    INSERT INTO foo (str,dmy,num) VALUES ("AAA", TODAY, 12.34)
    DISPLAY "*** Serial = ",SQLCA.SQLERRD[2]
    
    INSERT INTO foo (str,dmy,num) VALUES ("BBB", TODAY, 23.45)
    DISPLAY "*** Serial = ", SQLCA.SQLERRD[2]
    

    -- Static SQL example
    SELECT COUNT(*) INTO foo_count FROM foo
    DISPLAY "*** Count = ",foo_count

    -- Cursor Example
    LET sql = "SELECT str, dmy, num FROM foo WHERE id = ? "
    DECLARE fetch_curs CURSOR FROM sql

    LET id = 1 
    OPEN fetch_curs USING id
    FETCH fetch_curs INTO rec.*

    DISPLAY  "*** Fetch = ", rec.*

    -- Deliberate error
    SELECT COUNT(*) FROM foo2

END MAIN

FUNCTION fgl_sqldebug_on()
    CALL fgl_sqldebug(3)
END FUNCTION

FUNCTION fgl_sqldebug_off()
    CALL fgl_sqldebug(0)
END FUNCTION