Question
What do these messages from the db2fmp process mean?
Cause
This technote provides some FAQs regarding messages in the db2diag.log in regards to db2fmp processes used to run non-SQL routines such as Java and C.
Scenario #1: Threads in db2fmp process, SQL1042
When the DB2 registry variable DB2_MAX_THREADS_PER_FMP is set you may see the messages below which can be safely ignored. This registry variable was introduced as an enhancement to DB2 via IZ08425.
In some cases the SQL1042 is a legitimate error so its important to note that in this scenario "Max number of thread in fmp reached; no thread created" is the cause of the SQL1042. The SQL1042 can be safely ignored.
Please note that the SQL1042 is transparent to the application, so no errors will be returned to the application. DB2 automatically starts a new db2fmp process to service the existing or subsequent requests.
2011-01-10-11.31.12.480063-300 I34781A381 LEVEL: Warning
PID : 1200 TID : 1 PROC : db2fmp (Java) 0
INSTANCE: db2inst1 NODE : 000
EDUID : 1 EDUNAME: db2fmp (Java) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerMasterThreadListener,
probe:200
MESSAGE : Max number of thread in fmp reached; no thread created
2011-01-10-12.10.13.923352-300 I74680A573 LEVEL: Warning
PID : 1234 TID : 100 PROC : db2sysc
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-33648 APPID: 192.168.1.1.50234.11022217100
AUTHID : DB2INST1
EDUID : 608 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerMasterThreadReq,
probe:89
MESSAGE : FMP reported it could not create a new thread
DATA #1 : Hexdump, 4 bytes
0x000000020210F180 : 0000 0C05 ....
2011-01-10-10.02.25.454418-300 I2221A448 LEVEL: Severe
PID : 1234 TID : 100 PROC : db2sysc 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-51434 APPID: 10.111.41.13.56427.110218150224
AUTHID : DB2INST1
EDUID : 260 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerGetFmpThread, probe:20
RETCODE : ZRC=0xFFFFFBEE=-1042
Scenario #2: Operating system resource issue, SQL1042
The messages are very similar to Scenario #1 so how do we determine if the SQL1042 is legitimate? Work backwards and look for preceding messages originating from the same PID and TID.
In the case below we see the source of the error is originating from the operating system (OSERR) and the operating system API which returned the error (pthread_create). pthread_create() is an AIX API indicating that the operating system was unable to create a new thread in the db2fmp process. The root cause is likely an operating system limitation or resource issue when trying to create an additional thread due to the EAGAIN return code.
2011-01-01-13.01.03.345767-240 E287334A401 LEVEL: Severe (OS)
PID : 2609242 TID : 1 PROC : db2fmp (Java) 0
INSTANCE: db2inst1 NODE : 000
EDUID : 1 EDUNAME: db2fmp (Java) 0
FUNCTION: DB2 UDB, oper system services, sqloCreateAppThread, probe:100
CALLED : OS, -, pthread_create
OSERR : EAGAIN (11) "Resource temporarily unavailable"
2011-01-01-13.01.03.426469-240 I287736A455 LEVEL: Severe
PID : 2609242 TID : 1 PROC : db2fmp (Java) 0
INSTANCE: db2inst1 NODE : 000
EDUID : 1 EDUNAME: db2fmp (Java) 0
FUNCTION: DB2 UDB, trace services, sqlt_logerr_data (secondary logging
func, probe:0
MESSAGE : Failed to create app thread:
DATA #1 : Hexdump, 4 bytes
0x0FFFFFFFFFFFEF60 : 0000 000B ...
2011-01-01-13.01.03.426684-240 I288192A343 LEVEL: Severe
PID : 2609242 TID : 1 PROC : db2fmp (Java) 0
INSTANCE: db2inst1 NODE : 000
EDUID : 1 EDUNAME: db2fmp (Java) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerCreateWorkerThread,
probe:20
RETCODE : ZRC=0xFFFFFBEE=-1042
Scenario #3: SQL1042N returned on AIX platforms using Power7 processors
There is an incompatibility between the IBM JDK bundled with DB2 v9.7 and Power7. For details refer to the link db2setup or db2fmp (Java) abnormally terminated on Power7
Scenario #4: SQL1042N returned due to permission issue
Ensure the DB2 instance home directory has the permission below, otherwise the db2fmp may not be able to access files located in ~/sqllib/function
/home $ ls -la
drwxr-xr-x 14 db2inst1 db2admg 4096 Aug 04 10:51 db2inst1/
Check the stored procedure binaries in ~/sqllib/function to ensure they are world readable because the fenced userid is usually not the instance owner.
/home/db2inst1/sqllib/function:
-rw-r--r-- 1 db2fenc fencgrp 875 Jul 29 14:24 DUMMY_JAVASP.class
Check the permission of ~/sqllib/adm/db2fmp and ~/sqllib/adm/db2fmp32 to ensure the "other" group has privileges to execute these two files.
chmod o+r db2fmp
chmod o+r db2fmp32
After the change you should see:
-r-xr-xr-x 1 db2inst1 db2admg 59384 Jan 1 17:09 db2fmp
-r-xr-xr-x 1 db2inst1 db2admg 74743 Jan 1 17:09 db2fmp32
Scenario #5: Executing long running query
A remote DB2 client has abnormally terminated when executing a long running query which includes a call to a routine. These messages are informational in nature and can be ignored. However the application should contain some exception handling logic to handle any abnormal terminations. Under the covers DB2 will clean up any non-SQL routines being executed on behalf of the connection. one of the side effects is that the db2diag.log may contain a 0xFFFFFB38 ( SQL1224)
In the example below the message originating from the db2fmp process about "The database manager is not able to accept new requests..." is misleading. The message is originating from the JDBC (db2jcc.jar) used internally by the DB2 server to execute a Java routine and can be ignored. There is nothing wrong with the DB2 database server.
2011-01-12-12.08.33.158935-300 I6813000A541 LEVEL: Error
PID : 9644 TID : 172 PROC : db2sysc 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-20965 APPID: 192.168.1.1.33819.110220052256
AUTHID : DB2INST1
EDUID : 172 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, common communication, sqlcctcptest, probe:11
MESSAGE : Detected client termination
DATA #1 : Hexdump, 2 bytes
0xFFFFFFFF4B7F3376 : 0036 .6
2011-01-12-12.08.33.170419-300 I6813542A523 LEVEL: Error
PID : 9644 TID : 172 PROC : db2sysc 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-20965 APPID: 192.168.1.1.33819.110220052256
AUTHID : DB2INST1
EDUID : 172 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, common communication, sqlcctest, probe:50
MESSAGE : sqlcctest RC
DATA #1 : Hexdump, 2 bytes
0xFFFFFFFF4B7F346E : 0036
2011-01-01-12.08.33.170664-300 I6814066A503 LEVEL: Error
PID : 9644 TID : 172 PROC : db2sysc 0
INSTANCE: db2inst11 NODE : 000 DB : SAMPLE
APPHDL : 0-20965 APPID: 192.168.1.1.33819.110220052256
AUTHID : DB2INST1
EDUID : 172 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, base sys utilities, sqeAgent::AgentBreathingPoint, probe:10
CALLED : DB2 UDB, common communication, sqlcctest
RETCODE : ZRC=0x00000036=54
2011-01-01-12.08.33.173237-300 I6814570A507 LEVEL: Error
PID : 9644 TID : 172 PROC : db2sysc 0
INSTANCE: db2inst11 NODE : 000 DB : SAMPLE
APPHDL : 0-20965 APPID: 192.168.1.1.33819.110220052256
AUTHID : DB2INST1
EDUID : 172 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerInvokeFencedRoutine, probe:40
DATA #1 : Hex integer, 4 bytes
0x804B006D
DATA #2 : Hex integer, 4 bytes
0xFFFFFB38 /* SQL1224 */
2011-01-01-12.08.33.173599-300 E6815078A3474 LEVEL: Severe
PID : 9644 TID : 172 PROC : db2sysc 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-20965 APPID: 192.168.1.1.33819.110220052256
AUTHID : DB2INST1
EDUID : 172 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerReturnFmpToPool, probe:900
DATA #1 : String, 50 bytes
Marking fmp as unstable, fmp is forced or aborted:
DATA #2 : Boolean, 1 bytes
true
DATA #3 : String, 20 bytes
Fmp entry use count:
DATA #4 : unsigned integer, 4 bytes
1
DATA #5 : String, 8 bytes
Fmp TID:
DATA #6 : Hexdump, 4 bytes
0x000000020079F650 : 0000 0037 /* 0x37 = 55 */
DATA #7 : String, 8 bytes
Fmp row:
DATA #8 : sqlerFmpRow, PD_SQLER_TYPE_FMP_ROW, 496 bytes
fmpPid: 15781
When executing Java routines one additional side effect is that the message below will appear in the db2diag.log. This message is misleading because there is nothing wrong with the database manager on the DB2 server. The message originates from the JDBC driver which is local to the DB2 server used to execute Java routines. This message can be safely ignored.
2011-01-01-12.08.33.213727-300 I6840110A1387 LEVEL: Warning
PID : 15781 TID : 55 PROC : db2fmp (Java) 0
INSTANCE: db2inst1 NODE : 000
EDUID : 55 EDUNAME: db2fmp (Java) 0
FUNCTION: DB2 UDB, BSU Java support, sqlejLogException, probe:10
DATA #1 : String, 962 bytes
com.ibm.db2.jcc.am.DisconnectNonTransientException: [jcc][2055][11259][3.61.86] The database manager is not able to accept new requests, has terminated all requests in progress,
or has terminated this particular request due to unexpected error conditions detected at the target system. ERRORCODE=-4499, SQLSTATE=58009
at com.ibm.db2.jcc.am.ed.a(ed.java:321)
at com.ibm.db2.jcc.t4.ab.T(ab.java:1264)
...
Scenario #6: SQL1131 or SQL4302
This indicates the non-SQL routine was abnormally terminated. This is usually not a serious error as long as the application is coded to handle these exceptions and the messages do not appear frequently e.g. once a month.
2011-02-02-15.01.23.476662-240 I299008A471 LEVEL: Warning
PID : 8245982 TID : 1280 PROC : db2fmp (Java) 0
INSTANCE: db2inst1 NODE : 000
EDUID : 12080 EDUNAME: db2fmp (Java) 0
FUNCTION: DB2 UDB, trace services, sqlt_logerr_data (secondary logging
func, probe:0
MESSAGE : Thread of db2fmp terminated with nonzero rc
DATA #1 : Hexdump, 4 bytes
0x000000011E7685EC : FFFF FB95 /* SQL1131 */ ...
2011-02-02-15.01.23.883044-240 I299480A453 LEVEL: Severe
PID : 8245982 TID : 1280 PROC : db2sysc 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-40776 APPID: 192.168.1.10.47637.100712165705
AUTHID : DB2INST1
EDUID : 17812 EDUNAME: db2agent (CLNPIS) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerDisassociateWithFmp,
probe:30
RETCODE : ZRC=0xFFFFFB95=-1131
Scenario #7: Marking fmp as unstable
This message is returned when DB2 decides to shut down a db2fmp process and can be part of normal DB2 operations. DB2 automatically picks a new db2fmp or creates a new db2fmp process to execute any subsequent calls to stored procedures or UDFS.
To determine whether this message is more than informational please check for additional db2diag.log entries around the same timestamp which return a ZRC return code, 0xFFFFxxxx return code or an error from the operating system (OSERR). Please use the db2diag tool to decode these return codes.
This message may also be returned when:
- DBM CFG parameter KEEPFENCED=NO since DB2 would terminate any db2fmp process after a routine has completed execution.
- FORCE APPLICATIONS was issued or if "db2stop force" was called.
2011-01-10-12.01.55.448367+000 E288536A3366 LEVEL: Severe
PID : 582 TID : 9823 PROC : db2sysc 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-40834 APPID: 10.69.63.248.47961.100712170155
AUTHID : DB2INST1
EDUID : 18069 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, routine_infrastructure, sqlerMasterThreadReq,
probe:901
DATA #1 : String, 50 bytes
marking fmp as unstable:
DATA #2 : String, 8 bytes
Fmp TID:
DATA #3 : Hexdump, 4 bytes
0x078000000113B770 : 0000 0000 ....
DATA #4 : String, 8 bytes
Fmp Row:
DATA #5 : sqlerFmpRow, PD_SQLER_TYPE_FMP_ROW, 504 bytes
fmpPid: 2609242
fmpPoolList Ptr: 0x0000000000000000 fmpForcedList Ptr:
0x0000000000000000
nextFmpCB Ptr: 0x0780000000ed6980 prevFmpCB Ptr: 0x078000000100ea20
fmpIPCList Ptr: 0x0780000001138960
stateFlags: 0x00000013 numFmp32Attaches: 0
numActiveThreads: 41 numPoolThreads: 0
fmpCodePage: 1252 fmpRowUseCount: 42
...
...
2011-01-10-12.01.56.172884+000 I2049780A492 LEVEL: Warning
PID : 7131362 TID : 1 PROC : db2agent (SAMPLE) 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-1333 APPID: 192.168.1.10.17420.0710250420
AUTHID : DB2INST1
FUNCTION: DB2 UDB, trace services, sqlt_logerr_data, probe:0
MESSAGE : Removing FMP from pool
DATA #1 : Hexdump, 16 bytes
2011-01-10-12.01.56.172890+000 I2040223A1335 LEVEL: Error
PID : 7131362 TID : 1 PROC : db2agent (SAMPLE) 0
INSTANCE: db2inst1 NODE : 000 DB : SAMPLE
APPHDL : 0-1333 APPID:192.168.1.10.17420.0710250420
AUTHID : DB2INST1
FUNCTION: DB2 UDB, oper system services, sqlossig, probe:10
MESSAGE : Sending SIGKILL to the following process id
DATA #1 : signed integer, 4 bytes
7016538
The SIGKILL can be safely ignored since it is returned when DB2 brings down the db2fmp.
The meaning of the stateFlags can be decoded via the chart provided in the technote belowAccumulation of db2fmp (Java) processes.
Scenario #8: Messages related to Java memory
Please see the technote db2fmp (Java) Memory Issues in the links below.
Scenario #9: Data Partitioned System
On systems using data partitioning, please ensure that the fenced userid exists on ALL partitions. Otherwise SQL1042C may be returned. Most of the DB2 table snapshot functions are implemented as non-SQL routines.
db2 "select count(*) from SYSIBMADM.TBSP_UTILIZATION"
SQL1042C An unexpected system error occurred. SQLSTATE=58004
Scenario #10: SQL0952N Processing was cancelled due to an interrupt.
If the application calling the routine cancelled the call, -952 will be reported in the db2diag.log. The application may have canceled the routine because there was an error or it may have logic to terminate the routine call if no result is returned within a timeout. To investigate further check the application log and the application developer to determine what may have caused the application to cancel the call the to routine.
Other Aids
The db2diag command can be used to translate any hexadecimal messages such as 0xFFFFFB38 or ZRC=0x8136001C code into a meaningful SQLCODE.
db2diag -rc FFFFFB38
Input ECF string 'FFFFFB38' parsed as 0xFFFFFB38 (-1224).
ERROR: ../sqz/sqlzwhatisrc.C:
Input ZRC 0xFFFFFB38 (-1224) cannot be identified as a V7 or V6 ZRC value