Understand debuglog performance comments

johndanter

johndanter

Legendary Poster
Hi folks

I have an issue with WO Completion in that now and again it takes an age.
I use JDETrace to see the long running BSFNs SQLs etc and I've found selects to F41021 in XF41021 being the culprit when called from within VerifyAndGetItemLocation from F3111WOIssuesEditLine (10 second average!!!)

Can someone please explain what the E1 system or Oracle database maybe doing in the gaps between 09:01:10 > 09:01:11 > 09:01:21 > 09:01:21 Is it really taking 10 seconds below?

If so why are these SQLs taking 10 seconds in my log yet when when I run them outside of E1 they fly?

Oct 11 09:01:10 4130295624 5556 WRK:Starting jdeCallObject SELECT * FROM UTDTA.F41021 WHERE ( LIITM = 4429699.000000 AND LIMCU = ' 728' AND LILOCN = 'LI01IN ' AND LILOTN = '201511100129 ' )
Oct 11 09:01:11 6840005624 5556 WRK:Starting jdeCallObject ORACLE DBFetch conn=0B62ADE8 requ=0F82EA48 maxrows=94
Oct 11 09:01:21 89000 5624 5556 WRK:Starting jdeCallObject ORACLE DBFetch conn=0B62ADE8 requ=0F82EA48 fetched=1
Oct 11 09:01:21 89001 5624 5556 WRK:Starting jdeCallObject ORACLE usage 09:01:10 (16 FTCH 16 rows 0 LOBs) (1 UPD) (0 INS 0 rows) (0 DEL) (0 MISC)

​Oct 11 09:01:31 5870255624 5556 WRK:Starting jdeCallObject SELECT * FROM UTDTA.F41021 WHERE ( LIITM = 4826070.000000 AND LIMCU = ' 728' AND LILOCN = 'LI01IN ' AND LILOTN = '201510210383 ' )
Oct 11 09:01:40 2160005624 5556 WRK:Starting jdeCallObject ORACLE DBFetch conn=0B62ADE8 requ=0F837288 maxrows=94
Oct 11 09:01:45 2560005624 5556 WRK:Starting jdeCallObject ORACLE DBFetch conn=0B62ADE8 requ=0F837288 fetched=1
Oct 11 09:01:45 2560015624 5556 WRK:Starting jdeCallObject ORACLE usage 09:01:31 (14 FTCH 14 rows 0 LOBs) (3 UPD) (2 INS 2 rows) (0 DEL) (0 MISC)

Oct 11 09:01:45 4670505624 5556 WRK:Starting jdeCallObject SELECT * FROM UTDTA.F41021 WHERE ( LIITM = 5038825.000000 AND LIMCU = ' 728' AND LILOCN = 'LI01IN ' AND LILOTN = '201512230034 ' )
Oct 11 09:01:51 9490005624 5556 WRK:Starting jdeCallObject ORACLE DBFetch conn=0B62ADE8 requ=0F837288 maxrows=94
Oct 11 09:01:54 42000 5624 5556 WRK:Starting jdeCallObject ORACLE DBFetch conn=0B62ADE8 requ=0F837288 fetched=1
Oct 11 09:01:54 42001 5624 5556 WRK:Starting jdeCallObject ORACLE usage 09:01:45 (13 FTCH 12 rows 0 LOBs) (0 UPD) (0 INS 0 rows) (0 DEL) (0 MISC)


Thanks

John
 
Since the select statement is selecting on the PK of the table I don't think it would be anything like a table scan or anything like that.

Look into blocking at the DB level. This can be caused by both transaction processing and by the JDEBASE locking APIs. When the F41021 is updated most code that updates this table *correctly* uses the DB record locking APIs. Poorly implemented code or bugs around both of these DB technologies can cause blocking.
 
Good thinking. It's only a select mind, not an update. Would locking be an issue?

It's base E1 so I'll be shocked ;)
 
Last edited:
Back
Top