Non-responsive UI thread detected?

Ignition
,
1

Using Vision 8.1.16.

Have a window where there’s a root container property called initialData that is a named query based on one id parameter.

All my components have a custom property called initialValue of the form
try({Root Container.initialData}[0, 'someColumnName'], 'someDefaultValue') and then the property I want displayed is bound to this initial data.

I also have a second dataset property on my root container called initialVendorData, which is based on an id found in the first dataset (the id is extracted via an expression again similar to above, and that is fed to the named query populating initialVendorData).

When I open the window it will take over 5 seconds before everything is populated.

I was notified of the following
15:27:57.913 [EDT-Watchdog-1] INFO edt-watchdog - Non-responsive UI thread detected. Stack saved at 'C:\Users\bkarabinchak\.ignition\cache\gw192.168.57.190_8088\C2\NonResponsiveEdt-2022-04-28_152834.json'

The contents of the file are as follows

NonResponsiveEdt-2022-04-28_152834.json (43.1 KB)

I am hoping someone can help me interpret the issue. This is a dev system that is running off a VM that is hosting the gateway and MySQL database so it may just be a ram/hardware issue, but it is happening consistently now and it was not earlier today or earlier this week for that matter so I am fearful that some code change I made is causing some memory leak or something.

2

I can just tell you what I see in the stack trace, not sure it will be useful:

You have a query binding that runs, sets the data on a table, which fires a property change, and then you have some script executing in response to that property change.

All of this happens on the UI thread and it’s causing your UI to lock up while it runs.

1 Like
3

Ok so I do have two tables on this, a Detailed table which has a initialValue property which is it’s own named query. This table does not have a property change script, but it does have an
configureEditor script

	if colName == 'officeLocationName':
                # self.locationChoices is populated by another named query
		locationNames = system.dataset.toPyDataSet(self.locationChoices)
		options = []
		for (idx, name) in locationNames:
			options.append((name, name))
		return {'options': options}

and an onCellEdited

	import windows.VendorPO
	print colName
	self.data = system.dataset.setValue(self.data, rowIndex, colIndex, newValue)
	if colName in ('taxable', 'officeLocationName'):
		windows.VendorPO.refreshTable(self)

I don’t think these get triggered by the property change though.

I think it is the second named table, named Overview, which has a data property expression binding using the Simulation Aids module view() function, I don’t have anything else that is based on the dataset from the Detailed table.

Tagging @pturmel

I think it may be my own fault here with using jython functions inside view. I realized I could use built in jython functions or custom jython functions in the pseudo-sql and I do and I wonder if that is making things run slower.

Here is the data expression (formatted for easier reading)

view("system.aggregate.sum(orderedButNotConfirmed) as Ordered,
system.aggregate.sum(confirmedByVendor) as Confirmed,
system.aggregate.sum(receivedByPSI) as Received,
system.aggregate.sum(billedToPSI) as Billed, 
system.aggregate.sum(paidByPSI) as Paid, 
parentPartId, name[0] as Name, 
description[0] as Description, 
system.aggregate.count(ordering) as Quantity, 
unitcost[0] as Cost,
system.aggregate.sum(unitcost) as TotalCost, 
all(taxable) as Taxable, 
system.aggregate.sum(taxAmount) as TaxAmount, new_dtype.dataset.allSameOrMixed(officeLocationName)  as Location, 
ordering[0] as ordering 
Group By parentPartId, 
ordering Order By ordering",
{Root Container.DetailedView.inventoryListDetailed.data})

I use jython all keyword to check off a check box if all the checkboxes in the detailed view are checked, or off if they’re not all checked.

I then have my custom function new_dtype_dataset.allSameOrMixed for one column - basically I want to show the column value for the group if they are all the same or show Mixed Locations if they are mixed. The function is

def allSameOrMixed(l):
   """
   Test to see how this works
   """
   mylist = [x for x in l]
   if all(x==l[0] for x in l):
   	return l[0]
   else:
   	return 'Mixed Locations'

I wonder if this is what is taking so long and locking up the UI as my custom function is not in java but only jython. Though the Detailed tables dataset is normally 10 rows or less as well.

I can provide more details to any questions.

4

Turn on debug mode for the view() expression function. It will report the jython it generates and runs on your behalf, and timing for every execution. It will be obvious if this is firing more than expected.

It does run on the foreground thread.

{ BTW, you can omit system.aggregate. inside of view() itself, which will be obvious when you look at the generated jython. }

That is the reason I made this use python expressions. By itself, that shouldn't be a problem. How many rows are you asking view() to group?

1 Like
5

Why did you feel the need to make mylist in your custom function?

6

I seem to be having a similar message in output console with 8.1.16 -
16:09:27.429 [EDT-Watchdog-1] INFO edt-watchdog - Non-responsive UI thread detected. Stack saved

I am creating an expression tag via script that reads from newly created opc tags. It takes about 2 sec for the opc values to come in and for the expression value to calculate the summed value.
I Sleep (5) to give time for the tag to get good data.
Then i check the quality of the expression tag and if good then i use the value for validation.
Very simple code but haven’t seen this error message before.

CODE snippit
##Create test_tags to check if is MLII device
try:
project.tags.folder.createFolder(’[default]’,‘Multiload_Test’) #Create Folder
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_1’, ‘MLII_Test’, ‘1.HR0’) #Char 1 - M
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_2’, ‘MLII_Test’, ‘1.HR1’) #Char 2 - u
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_3’, ‘MLII_Test’, ‘1.HR2’) #Char 3 - l
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_4’, ‘MLII_Test’, ‘1.HR3’) #Char 4 - t
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_5’, ‘MLII_Test’, ‘1.HR4’) #Char 5 - i
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_6’, ‘MLII_Test’, ‘1.HR5’) #Char 6 - L
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_7’, ‘MLII_Test’, ‘1.HR6’) #Char 7 - o
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_8’, ‘MLII_Test’, ‘1.HR7’) #Char 8 - a
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_9’, ‘MLII_Test’, ‘1.HR8’) #Char 9 - d
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_10’, ‘MLII_Test’, ‘1.HR9’) #Char 10 - space
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_11’, ‘MLII_Test’, ‘1.HR10’) #Char 11 - I
project.tags.tag.createOpc(’[default]/Multiload_Test/’, ‘Char_12’, ‘MLII_Test’, ‘1.HR11’) #Char 12 - I

		##Create Expression Tag
		project.tags.tag.createExpression('[default]/Multiload_Test/', 'Char_Sum',
			'toInt({[.]Char_1}) + toInt({[.]Char_2}) + toInt({[.]Char_3}) + toInt({[.]Char_4}) + toInt({[.]Char_5}) + toInt({[.]Char_6}) +	toInt({[.]Char_7}) + toInt({[.]Char_8}) + toInt({[.]Char_9}) + toInt({[.]Char_10}) + toInt({[.]Char_11}) + toInt({[.]Char_12})')
		
		sleep(5)		#wait 2 sec to give tags time to get good reading
		
		##Get data quality of Char_Sum tag
		tag = system.tag.readBlocking("[default]/Multiload_Test/Char_Sum")[0]
		
		print tag.quality
		print tag.value

Any reason for this non-responsive UI warning?

7

I think you answered it yourself...

6 Likes
8

Ok, I will turn on debugging, remove the aggregates. At most so far its been maybe 15 rows? This whole thing is for making purchase orders so its not that many rows.

And good call about the mylist - I think I did that initially for debugging/to see what was possible, but I obviously don’t need it so I will remove it.

Here are the log results without removing mylist as of now. I open the window the first time it loads quickly, then any subsequent opening is slow.

Results:

image

image

image

Here are the results without the mylist variable
I see three similar logs

view() execution time 65228 us
view() execution time 3928 us
view() execution time 3598 us

Don’t know why I see three execution times though - perhaps I have some issue where it’s executing three times or is this expected?

I think this is the jython you were referencing -

Message: from system.aggregate import *
_groups = {}
for _r in xrange(_from.rowCount):
parentPartId = _from.getValueAt(_r, 1)
orderedButNotConfirmed = _from.getValueAt(_r, 2)
confirmedByVendor = _from.getValueAt(_r, 3)
receivedByPSI = _from.getValueAt(_r, 4)
billedToPSI = _from.getValueAt(_r, 5)
paidByPSI = _from.getValueAt(_r, 6)
name = _from.getValueAt(_r, 9)
description = _from.getValueAt(_r, 10)
unitcost = _from.getValueAt(_r, 11)
taxable = _from.getValueAt(_r, 12)
taxAmount = _from.getValueAt(_r, 13)
officeLocationName = _from.getValueAt(_r, 15)
ordering = _from.getValueAt(_r, 17)
_groupkey = (parentPartId, ordering,)
if _groupkey in _groups:
_grouprow = _groups[_groupkey]
_grouprow[0].append(parentPartId)
_grouprow[1].append(orderedButNotConfirmed)
_grouprow[2].append(confirmedByVendor)
_grouprow[3].append(receivedByPSI)
_grouprow[4].append(billedToPSI)
_grouprow[5].append(paidByPSI)
_grouprow[6].append(name)
_grouprow[7].append(description)
_grouprow[8].append(unitcost)
_grouprow[9].append(taxable)
_grouprow[10].append(taxAmount)
_grouprow[11].append(officeLocationName)
_grouprow[12].append(ordering)
else:
_groups[_groupkey] = [[parentPartId], [orderedButNotConfirmed], [confirmedByVendor], [receivedByPSI], [billedToPSI], [paidByPSI], [name], [description], [unitcost], [taxable], [taxAmount], [officeLocationName], [ordering]]

_rows =
for _grouprow in _groups.itervalues():
parentPartId, orderedButNotConfirmed, confirmedByVendor, receivedByPSI, billedToPSI, paidByPSI, name, description, unitcost, taxable, taxAmount, officeLocationName, ordering, = tuple(_grouprow)
Ordered = system.aggregate.sum(orderedButNotConfirmed)
Confirmed = system.aggregate.sum(confirmedByVendor)
Received = system.aggregate.sum(receivedByPSI)
Billed = system.aggregate.sum(billedToPSI)
Paid = system.aggregate.sum(paidByPSI)
parentPartId = parentPartId[0]
Name = name[0]
Description = description[0]
Quantity = system.aggregate.count(ordering)
Cost = unitcost[0]
TotalCost = system.aggregate.sum(unitcost)
Taxable = all(taxable)
TaxAmount = system.aggregate.sum(taxAmount)
Location = new_dtype.dataset.allSameOrMixed(officeLocationName)
ordering = ordering[0]
_orderkey = (ordering,)
_rows.append([_orderkey, [Ordered, Confirmed, Received, Billed, Paid, parentPartId, Name, Description, Quantity, Cost, TotalCost, Taxable, TaxAmount, Location, ordering]])

_rows.sort()
_rows = [x[1] for x in _rows]

__retv = system.dataset.toDataSet(_resultColumns, _rows)

Time: Fri Apr 29 9:11:21AM
Severity: DEBUG
Logger: com.automation_pros.simaids.View

9

A tiny thing I noticed as well that seems like a bug but in the edt-watchdog logs the path is missing a separator of some kind

Message
Non-responsive UI thread detected. Stack saved at
'C:Usersbkarabinchak.ignitioncachegw192.168.57.190_8088C1NonResponsiveEdt-2022-04-29_094349.json'
10

Not expected. It reports once per execution. The first execution's time (65 ms) is typical for the parse/compile overhead of the pseudo-SQL. The following executions (3-4 ms) are typical for ordinary workloads.

I'd guess your use of the view() function is not the culprit. At least not by itself.

1 Like
11

Ok interesting . I will call Ignition now. The UI delay is 5/6 seconds so I don’t think the 65 millseconds view is the main issue, even if it’s executing 3 times for a total of about 75 milliseconds.

Oddly enough, the first time I open the window, it will load fast, but all subsequent openings will have the 5 second delay.

I will update this thread later on if I have an answer.

12

Isn’t the query you’re running on the UI the obvious first place to look?

13

There are only two named queries with the WHERE clause is on the index primary key idx. The first table only has 2 records as it’s something we are currently developing, and the second table only has ~400 records so I don’t think that the query is what is being so slow but I will verify this to eliminate it as a possibility.

Both of my EXPLAIN statements for both named queries look like
image

and when tested execute under .1 seconds on average. I don’t see either of these queries appear in my slow query logs either. So I don’t think they are it.

I have opened a ticket with Ignition tech support so I will see what it is going on.

Edit: Just checked. Seemed like at it’s worst, it could be contributing, but the average execution time seems like it generally should not be a problem

image
image852×275 20.9 KB