How to debug this slow request?

[JohanR]

Hi,

I have a browse list with EIP on a dropdown to update the item qty
Only the row is updated currently.
I have also attached a debug logfile of when I click the dropdown to when the page is updated.
The update code is super quick, but lines below is the problem.
How and where can I debug this?


These lines in the attached debug log take 7secs to execute with the busy wheel displaying

Currently trying the browser devtools to see but was hoping there might be some feedback from someone.

thanks
Johan


63   13:20:21.239   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
64   13:20:21.239   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end
65   13:20:22.249   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
66   13:20:22.249   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end
67   13:20:23.240   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
68   13:20:23.240   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end
69   13:20:24.242   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
70   13:20:24.242   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end
71   13:20:25.239   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
72   13:20:25.239   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end
73   13:20:26.241   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
74   13:20:26.242   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end
75   13:20:27.246   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 start
76   13:20:27.246   28064   xtvcweb.exe   [NetDLL] [2] CallBackWindowSrc() : NTThread Event : 523 end

I've had a similar issue before with a different procedure and when I reworked the procedure it resolved the issue without me knowing what caused the problem.

[Bruce]

These are just timer events in the NetTalk DLL.
They're unrelated to your issue.

My guess is that the reply to the browser is not completing. ie you have some code in the thread, after the drop down is populated, which delays the ending of the thread. In that case the connection is not closed, so the browser does not start processing the reply.

Cheers
Bruce

[JohanR]

Hi Bruce

Thanks for the reply.

Are you referring to the code in the "Client Side" server code button embed
the only code I have there executes super fast.

      ds_OutputDebugString('TVCweb MyCode Start:' & format(clock(),@t06))
      do calc_rest_of_flds 
      ds_OutputDebugString('TVCweb MyCode End:' & format(clock(),@t06))

Or is there code somewhere else that is still executing on a thread even though the page is populated?

thanks

Johan

[JohanR]

Hi Bruce

Think I found the line that takes roughly 5secs
In the LoadViewRecord

It's the next(p_view) between 5555 and 6666
Still using TPS, not sure if this is an issue

Below the code and the view structure.

My next step is going to duplicate and handcode the action of the view and see if it does the same and also to see if there is something to be done.

Any ideas highly appreciated.

Johan


NetWebServerWorkerBase.LoadViewRecord  Procedure(View p_View,File p_File,Key p_Key)
err Long
f   String(1024)
  code

  self.trace('TVCweb LoadViewRecord 1111:' & format(clock(),@t06))     
  f = p_view{prop:filter}
  self.trace('TVCweb LoadViewRecord 2222:' & format(clock(),@t06))     
 
  p_view{prop:filter} = ''
  self.trace('TVCweb LoadViewRecord 3333:' & format(clock(),@t06))     
  self.trace('TVCweb LoadViewRecord 3333Filter=:' & p_View{prop:filter})     
 
  self.AddKeyToFilter(p_View,p_File,p_Key)
 
  self.trace('TVCweb LoadViewRecord 4444:' & format(clock(),@t06))     
  self.trace('TVCweb LoadViewRecord 4444Filter=:' & p_View{prop:filter})     
 
  set(p_view)
 
  self.trace('TVCweb LoadViewRecord 5555:' & format(clock(),@t06))     
  next(p_view)
  self.trace('TVCweb LoadViewRecord 6666:' & format(clock(),@t06))     
 
  err = errorcode()
  self.trace('TVCweb LoadViewRecord 7777:' & format(clock(),@t06))     
 
  p_view{prop:filter} = self.AssignFilter(f)
  self.trace('TVCweb LoadViewRecord 8888:' & format(clock(),@t06))     
 
  return err



View:item       View(item)
                      Project(ite:item_isn)
                      Project(ite:item_desc)
                      Project(ite:item_amt)
                      Project(ite:item_qty)
                      Project(ite:item_gr_total)
                    END ! of ThisView

[rjolda]

Johan,
I am not sure if it applies here but using the UPPER on any searches really speeds up browses.
 e.g instead of where ITM:UID = thisUID  go for  where UPPER(ITM:UID) = UPPER(thisUID).   This takes out the mixed case filtering and speeds up queries.
Ron

[JohanR]

Hi Ron

thanks for the idea, am looking into it.
The key is Case sensitive and the filter is constructed by the EIP code

My understanding is if Case sensitive key then UPPER not required?


thanks

Johan

[JohanR]

Hi Bruce

Any advice on how to find this possible problem?

Been chasing all sorts of things past few days, but still having an issue.


From your post earlier
>>>>>>>>>>>>>>>>>>>>
My guess is that the reply to the browser is not completing. ie you have some code in the thread, after the drop down is populated, which delays the ending of the thread. In that case the connection is not closed, so the browser does not start processing the reply.
>>>>>>>>>>>>>>>>>>>>

thanks

Johan

[JohanR]

Hi,

Currently have had to remove the EIP dropbox and replaced it with a popup UpdateForm.

Will return to the problem when I get a chance, and will post any findings.

thanks

Johan

[Jane]

Hi, Johan,
Not sure I'm understanding?  Do you have a browse with an EIP column and the browse itself is slow to load?

Is the browse page-loaded or file-loaded? How many items are in the EIP dropdown list?

I think that the browse with EIP populates all the EIP possibilities for the column for each row.  Which, if you have 15 rows in the browse, would mean it needs to process all of the rows for the EIP selections 15 times.  If file-loaded, then for the entire browse.  If you only have a few choices that might be reasonable, but if there's a long list there will be a lot of overhead.

When you use an update form, the EIP selections are only populated once when you open the form.

[JohanR]

Hi Jane

Thanks for that idea, will have a look,
it's a decent length, perhaps 20 entries, so will play a roll, but don't think that's the culprit.

Also need to cleanup my procedure and all debug lines, and look with fresh eyes. 

thanks


Johan

[JohanR]

Hi Jane

Asked in the NT user group last night, still no resolve,
but the problem is outside of the procedures.

Once I have more info will post what I've found


thanks

Johan

[Jane]

I watched the webinar recording, Johan.

Helpful hint - Ctrl+Shift+X clears the log in debugview++

[rjolda]

Hi Johan,
I was at the webinar. I don't have much to offer but ProcessLink seems to be a focal point for everything that happens.  If I were to try to look at this I would look at web_handler and begin to search with maybe what is going through the ProcessLink AFTER your browse procedure.  CLOSES....  A very crude way that I can think of is to put a p_web.Trace('hi, I am procedure Browse_city..., etc) at the start of each procedure.  Then you can watch your DebugView for what happens AFTER your browse closes.  There are probably more elegant ways to do this.  Also, it might be doing some housekeeping which might not get you a trace statement.  But then you might know what it is NOT..  Also, if you can slice out this browse and part of the program and test it OUTSIDE your full program, you might gain some insights.
Ron

[Bruce]

Hi Johan,

If it's the NEXT that takes the time, then your VIEW is likely doing a full table scan (perhaps multiple of them in TPS) to construct the VIEW. Post the View declaration here, the file declarations (for files included in the View) and also the contents of the View Filter.

Cheers
Bruce