Updating Label text

[BartStolarek]

I'm looking to speed up how fast all the labels are updated, since its taking almost 10 seconds.

Granted, I have 96 labels on this window, but when I tried to build the same app in Kivy, the labels updated instantly.

My function 'calculate' has two parts to it

1. Calculate new values
2. Update the new values to label text.

I'm 100% certain that its the labels.text being set that is taking a lot of time, seems to be 10 labels per second is the rate.

Would anyone know of a method/pattern/improvement I could do? I believe its the searching for key:value pair in the dict that is the time waster.

Here is a snippet of the first 20 or so lines of my calculate function:

> def calculate_set_labels():
>             """
>             This function calculates the dashboard figures, and updates the corresponding labels
> 
>             Args:
>                 none
>             """
> 
>             widgets = self.main_window.widgets
>             
>             user_Jess = self.controller.find_user_by_name('Jess')
>             user_Bart = self.controller.find_user_by_name('Bart')
>             
>             print("Setting Labels")
>             
>             
>             # Income 
>             print("\t Calculating Income variables")
>             jess_income = round_up(user_Jess.income * self.frequency_conversions[self.frequency], 2)
>             bart_income = round_up(user_Bart.income * self.frequency_conversions[self.frequency], 2)
>             total_income = jess_income + bart_income
>             jess_income_percent = jess_income / total_income
>             bart_income_percent = bart_income / total_income
>             total_income_percent = total_income / total_income
>             
>             print("\t Setting Income Labels")
>             widgets["incomes_details_user_1_row_1_dollar_label"].text = f'${round(jess_income,2)}'
>             widgets["incomes_details_user_1_row_1_percent_label"].text = f'{round((jess_income_percent)* 100, 2)}%'
>             widgets["incomes_details_user_2_row_1_dollar_label"].text = f'${round(bart_income,2)}'
>             widgets["incomes_details_user_2_row_1_percent_label"].text = f'{round((bart_income_percent)* 100, 2)}%'
>             widgets["incomes_details_user_total_row_1_dollar_label"].text = f'${round(total_income,2)}'
>             widgets["incomes_details_user_total_row_1_percent_label"].text = f'{round((total_income_percent)* 100, 2)}%'

[freakboy3742]

What platform are you running this code on? I've just mocked up an example on macOS, and 100 labels update in <0.1 s; my guess is that this is a performance issue on one specific platform.

[BartStolarek]

Hey @freakboy3742, thanks for the quick response :), I'm developing on windows, but I'm getting same speed when running briefcase dev, as I do when running briefcase android run.

I also have 638 widgets on this window in total, so it might be the process of finding that ID in 638 widgets that is taking sometime (although I thought dict searches were a constant of O(1). Thinking I might need to review how I design my window.

I've updated the following to get some times:

> print(f"Checkpoint (Income) 1: Start")
>             checkpoint_1 = time.perf_counter()
>             widgets["incomes_details_user_1_row_1_dollar_label"].text = f'${round(jess_income,2)}'
>             label_time1 = time.perf_counter()
>             print(f"Label 1: {label_time1-checkpoint_1:.6f} seconds")
>             widgets["incomes_details_user_1_row_1_percent_label"].text = f'{round((jess_income_percent)* 100, 2)}%'
>             label_time2 = time.perf_counter()
>             print(f"Label 1: {label_time2-label_time1:.6f} seconds")
>             widgets["incomes_details_user_2_row_1_dollar_label"].text = f'${round(bart_income,2)}'
>             label_time3 = time.perf_counter()
>             print(f"Label 1: {label_time3-label_time2:.6f} seconds")
>             widgets["incomes_details_user_2_row_1_percent_label"].text = f'{round((bart_income_percent)* 100, 2)}%'
>             label_time4 = time.perf_counter()
>             print(f"Label 1: {label_time4-label_time3:.6f} seconds")
>             widgets["incomes_details_user_total_row_1_dollar_label"].text = f'${round(total_income,2)}'
>             label_time5 = time.perf_counter()
>             print(f"Label 1: {label_time5-label_time4:.6f} seconds")
>             widgets["incomes_details_user_total_row_1_percent_label"].text = f'{round((total_income_percent)* 100, 2)}%'
>             print(f"Label 1: {time.perf_counter()-label_time5:.6f} seconds")
>             print(f"Checkpoint_1: Done in {time.perf_counter()-checkpoint_1:.6f} seconds")

And this is the console print out:

There are 638 widgets
Setting Labels
         Setting Income Labels
Checkpoint (Income) 1: Start
Label 1: 0.027282 seconds
Label 2: 0.207283 seconds
Label 3: 0.212995 seconds
Label 4: 0.200965 seconds
Label 5: 0.212102 seconds
Label 6: 0.197604 seconds
Checkpoint_1: Done in 1.058254 seconds
         Fund Labels
         Saving Labels
         Expense Labels
Finished updating labels
Time taken to execute calculate_set_labels: 7.510716 seconds

I also ran a cProfile on my calculate_set_labels() with these (this is a bit of jargon to me at the moment, but might help):

>   
 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>     36480   16.718    0.000   16.783    0.000 box.py:15(set_bounds)
>     24672    1.276    0.000    1.279    0.000 base.py:82(set_bounds)
>   1615296    0.360    0.000    0.591    0.000 declaration.py:180(getter)
>  61152/96    0.260    0.000    1.482    0.015 pack.py:143(_layout_node)
> 17088/960    0.234    0.000    1.391    0.001 pack.py:231(_layout_row_children)
>   1615299    0.231    0.000    0.231    0.000 {built-in method builtins.getattr}
>  10560/96    0.140    0.000    1.480    0.015 pack.py:396(_layout_column_children)
>  61152/96    0.114    0.000   18.207    0.190 applicator.py:11(set_bounds)
>    794496    0.106    0.000    0.106    0.000 pack.py:133(scale)
>    416352    0.049    0.000    0.049    0.000 node.py:35(children)
>    327168    0.039    0.000    0.039    0.000 {built-in method builtins.max}
>     61152    0.038    0.000    0.059    0.000 layout.py:133(content_left)
>     61152    0.037    0.000    0.058    0.000 layout.py:122(content_top)
>    122208    0.020    0.000    0.020    0.000 layout.py:156(absolute_content_left)
>  61152/96    0.020    0.000    0.027    0.000 base.py:254(refresh_sublayouts)
>    196800    0.017    0.000    0.017    0.000 size.py:35(width)
>    192096    0.017    0.000    0.017    0.000 size.py:47(height)
>    122208    0.014    0.000    0.014    0.000 layout.py:144(absolute_content_top)
>     61056    0.008    0.000    0.008    0.000 layout.py:99(_origin_left)
>     61056    0.008    0.000    0.008    0.000 layout.py:87(_origin_top)
>        96    0.007    0.000    0.007    0.000 window.py:28(dpi)
>     47814    0.006    0.000    0.006    0.000 {built-in method builtins.hasattr}
>        96    0.005    0.000    0.005    0.000 label.py:19(set_text)
>        96    0.005    0.000    0.005    0.000 label.py:25(rehint)
>     24672    0.002    0.000    0.002    0.000 node.py:26(parent)
>       192    0.002    0.000    0.002    0.000 window.py:12(width)
>         1    0.001    0.001   19.738   19.738 app.py:231(calculate_set_labels)
>        96    0.001    0.000    1.491    0.016 pack.py:131(layout)
>       192    0.001    0.000    0.001    0.000 window.py:19(height)
>    192/96    0.001    0.000   19.731    0.206 base.py:240(refresh)
>        96    0.000    0.000    0.000    0.000 {built-in method builtins.round}
>        96    0.000    0.000   19.737    0.206 label.py:42(text)
>       192    0.000    0.000    0.000    0.000 size.py:39(width)
>        96    0.000    0.000   19.698    0.205 node.py:119(refresh)
>        16    0.000    0.000    0.000    0.000 {built-in method builtins.print}
>        96    0.000    0.000    0.000    0.000 box.py:43(rehint)
>       192    0.000    0.000    0.006    0.000 base.py:135(refresh)
>       288    0.000    0.000    0.000    0.000 size.py:4(__init__)
>       288    0.000    0.000    0.000    0.000 size.py:10(__eq__)
>       384    0.000    0.000    0.000    0.000 base.py:53(viewport)
>       192    0.000    0.000    0.000    0.000 size.py:51(height)
>       288    0.000    0.000    0.000    0.000 base.py:78(vertical_shift)
>         1    0.000    0.000   19.738   19.738 {built-in method builtins.exec}
>        20    0.000    0.000    0.000    0.000 app.py:221(round_up)
>        20    0.000    0.000    0.000    0.000 {built-in method math.ceil}
>         3    0.000    0.000    0.000    0.000 baseclass.py:49(get)
>         2    0.000    0.000    0.000    0.000 controller.py:133(find_user_by_name)
>        10    0.000    0.000    0.000    0.000 {built-in method time.perf_counter}
>         1    0.000    0.000   19.738   19.738 <string>:1(<module>)
>         1    0.000    0.000    0.000    0.000 app.py:469(main_window)
>         1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
>         1    0.000    0.000    0.000    0.000 {built-in method builtins.len}

[BartStolarek]

Log from android phone:

> 05-03 10:55:34.207  8610  8610 I python.stdout: There are 638 widgets
> 05-03 10:55:34.208  8610  8610 I python.stdout: Setting Labels
> 05-03 10:55:34.208  8610  8610 I python.stdout:          Setting Income Labels
> 05-03 10:55:34.208  8610  8610 I python.stdout: Checkpoint (Income) 1: Start
> 05-03 10:55:34.348  8610  8610 I python.stdout: Label 1: 0.140295 seconds
> 05-03 10:55:34.480  8610  8610 I python.stdout: Label 2: 0.131574 seconds
> 05-03 10:55:34.609  8610  8610 I python.stdout: Label 3: 0.128658 seconds
> 05-03 10:55:34.730  8610  8610 I python.stdout: Label 4: 0.121201 seconds
> 05-03 10:55:34.853  8610  8610 I python.stdout: Label 5: 0.123579 seconds
> 05-03 10:55:34.980  8610  8610 I python.stdout: Label 6: 0.126551 seconds
> 05-03 10:55:34.980  8610  8610 I python.stdout: Checkpoint_1: Done in 0.772014 seconds
> 05-03 10:55:34.980  8610  8610 I python.stdout:          Fund Labels
> 05-03 10:55:38.749  8610  8610 I python.stdout:          Saving Labels
> 05-03 10:55:42.612  8610  8610 I python.stdout:          Expense Labels
> 05-03 10:55:46.620  8610  8610 I python.stdout: Finished updating labels
> 05-03 10:55:46.620  8610  8610 I python.stdout: Time taken to execute calculate_set_labels: 12.412752 seconds
> 05-03 10:55:46.626  8610  8610 I python.stdout:          6654742 function calls (6444886 primitive calls) in 12.413 seconds
> 05-03 10:55:46.626  8610  8610 I python.stdout:
> 05-03 10:55:46.626  8610  8610 I python.stdout:    Ordered by: internal time
> 05-03 10:55:46.626  8610  8610 I python.stdout:
> 05-03 10:55:46.626  8610  8610 I python.stdout:    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
> 05-03 10:55:46.626  8610  8610 I python.stdout:     61056    5.788    0.000    6.644    0.000 box.py:12(set_child_bounds)
> 05-03 10:55:46.626  8610  8610 I python.stdout:   1469376    0.887    0.000    1.561    0.000 declaration.py:180(getter)
> 05-03 10:55:46.627  8610  8610 I python.stdout:  61152/96    0.850    0.000    4.667    0.049 pack.py:143(_layout_node)
> 05-03 10:55:46.627  8610  8610 I python.stdout: 17088/960    0.763    0.000    4.391    0.005 pack.py:231(_layout_row_children)
> 05-03 10:55:46.627  8610  8610 I python.stdout:   1469379    0.674    0.000    0.674    0.000 {built-in method builtins.getattr}
> 05-03 10:55:46.627  8610  8610 I python.stdout:  10560/96    0.445    0.000    4.662    0.049 pack.py:396(_layout_column_children)
> 05-03 10:55:46.627  8610  8610 I python.stdout:    794496    0.395    0.000    0.395    0.000 pack.py:133(scale)
> 05-03 10:55:46.627  8610  8610 I python.stdout:    122208    0.366    0.000    0.651    0.000 weakref.py:165(__setitem__)
> 05-03 10:55:46.627  8610  8610 I python.stdout:  61152/96    0.305    0.000    7.366    0.077 applicator.py:11(set_bounds)
> 05-03 10:55:46.627  8610  8610 I python.stdout:     61152    0.214    0.000    6.981    0.000 base.py:97(set_bounds)
> 05-03 10:55:46.627  8610  8610 I python.stdout:    327168    0.155    0.000    0.155    0.000 {built-in method builtins.max}
> 05-03 10:55:46.628  8610  8610 I python.stdout:    122208    0.144    0.000    0.144    0.000 weakref.py:353(__init__)
> 05-03 10:55:46.628  8610  8610 I python.stdout:    122208    0.141    0.000    0.199    0.000 weakref.py:106(remove)
> 05-03 10:55:46.628  8610  8610 I python.stdout:    416352    0.138    0.000    0.138    0.000 node.py:35(children)
> 05-03 10:55:46.628  8610  8610 I python.stdout:        96    0.126    0.001    4.916    0.051 pack.py:131(layout)
> 05-03 10:55:46.628  8610  8610 I python.stdout:     61152    0.112    0.000    0.170    0.000 layout.py:122(content_top)
> 05-03 10:55:46.628  8610  8610 I python.stdout:     61152    0.112    0.000    0.168    0.000 layout.py:133(content_left)
> 05-03 10:55:46.628  8610  8610 I python.stdout:     61152    0.104    0.000    0.104    0.000 weakref.py:195(get)
> 05-03 10:55:46.628  8610  8610 I python.stdout:    122208    0.093    0.000    0.142    0.000 weakref.py:348(__new__)
> 05-03 10:55:46.628  8610  8610 I python.stdout:        96    0.061    0.001    0.061    0.001 window.py:36(width)
> 05-03 10:55:46.629  8610  8610 I python.stdout:        96    0.060    0.001    0.060    0.001 window.py:40(height)
> 05-03 10:55:46.629  8610  8610 I python.stdout:    122208    0.058    0.000    0.058    0.000 {built-in method _weakref._remove_dead_weakref}
> 05-03 10:55:46.629  8610  8610 I python.stdout:    122208    0.053    0.000    0.053    0.000 layout.py:156(absolute_content_left)
> 05-03 10:55:46.629  8610  8610 I python.stdout:  61152/96    0.052    0.000    0.069    0.001 base.py:254(refresh_sublayouts)
> 05-03 10:55:46.629  8610  8610 I python.stdout:    122208    0.049    0.000    0.049    0.000 {built-in method __new__ of type object at 0x6fb8f85f30}
> 05-03 10:55:46.629  8610  8610 I python.stdout:    192096    0.046    0.000    0.046    0.000 size.py:47(height)
> 05-03 10:55:46.629  8610  8610 I python.stdout:    196800    0.045    0.000    0.045    0.000 size.py:35(width)
> 05-03 10:55:46.629  8610  8610 I python.stdout:    122208    0.035    0.000    0.035    0.000 layout.py:144(absolute_content_top)
> 05-03 10:55:46.629  8610  8610 I python.stdout:        96    0.029    0.000    0.029    0.000 label.py:37(set_text)
> 05-03 10:55:46.630  8610  8610 I python.stdout:    122208    0.027    0.000    0.027    0.000 base.py:55(container)
> 05-03 10:55:46.630  8610  8610 I python.stdout:        96    0.022    0.000    0.024    0.000 label.py:43(rehint)
> 05-03 10:55:46.630  8610  8610 I python.stdout:     61056    0.020    0.000    0.020    0.000 layout.py:87(_origin_top)
> 05-03 10:55:46.630  8610  8610 I python.stdout:     61056    0.020    0.000    0.020    0.000 layout.py:99(_origin_left)
> 05-03 10:55:46.630  8610  8610 I python.stdout:     47814    0.017    0.000    0.017    0.000 {built-in method builtins.hasattr}
> 05-03 10:55:46.630  8610  8610 I python.stdout:        16    0.002    0.000    0.002    0.000 stream.py:80(write)
> 05-03 10:55:46.630  8610  8610 I python.stdout:         1    0.002    0.002   12.413   12.413 app.py:231(calculate_set_labels)
> 05-03 10:55:46.630  8610  8610 I python.stdout:    192/96    0.001    0.000   12.378    0.129 base.py:240(refresh)
> 05-03 10:55:46.630  8610  8610 I python.stdout:        96    0.001    0.000    0.001    0.000 {built-in method builtins.round}
> 05-03 10:55:46.630  8610  8610 I python.stdout:        96    0.001    0.000   12.408    0.129 label.py:42(text)
> 05-03 10:55:46.631  8610  8610 I python.stdout:        96    0.001    0.000   12.283    0.128 node.py:119(refresh)
> 05-03 10:55:46.631  8610  8610 I python.stdout:       192    0.000    0.000    0.001    0.000 size.py:39(width)
> 05-03 10:55:46.631  8610  8610 I python.stdout:        96    0.000    0.000    0.001    0.000 box.py:25(rehint)
> 05-03 10:55:46.631  8610  8610 I python.stdout:       192    0.000    0.000    0.025    0.000 base.py:146(refresh)
> 05-03 10:55:46.631  8610  8610 I python.stdout:        32    0.000    0.000    0.002    0.000 stream.py:50(write)
> 05-03 10:55:46.631  8610  8610 I python.stdout:       192    0.000    0.000    0.000    0.000 size.py:51(height)
> 05-03 10:55:46.631  8610  8610 I python.stdout:       288    0.000    0.000    0.000    0.000 size.py:4(__init__)
> 05-03 10:55:46.631  8610  8610 I python.stdout:       288    0.000    0.000    0.000    0.000 size.py:10(__eq__)
> 05-03 10:55:46.631  8610  8610 I python.stdout:        32    0.000    0.000    0.002    0.000 {function TextLogStream.write at 0x6fb55fd510}
> 05-03 10:55:46.632  8610  8610 I python.stdout:         1    0.000    0.000   12.413   12.413 {built-in method builtins.exec}
> 05-03 10:55:46.632  8610  8610 I python.stdout:        16    0.000    0.000    0.002    0.000 {built-in method builtins.print}
> 05-03 10:55:46.632  8610  8610 I python.stdout:        64    0.000    0.000    0.000    0.000 {method 'splitlines' of 'str' objects}
> 05-03 10:55:46.632  8610  8610 I python.stdout:        20    0.000    0.000    0.000    0.000 app.py:221(round_up)
> 05-03 10:55:46.632  8610  8610 I python.stdout:         3    0.000    0.000    0.000    0.000 baseclass.py:49(get)
> 05-03 10:55:46.632  8610  8610 I python.stdout:        20    0.000    0.000    0.000    0.000 {built-in method math.ceil}
> 05-03 10:55:46.632  8610  8610 I python.stdout:        49    0.000    0.000    0.000    0.000 {built-in method builtins.len}
> 05-03 10:55:46.632  8610  8610 I python.stdout:        10    0.000    0.000    0.000    0.000 {built-in method time.perf_counter}
> 05-03 10:55:46.632  8610  8610 I python.stdout:         2    0.000    0.000    0.000    0.000 controller.py:133(find_user_by_name)
> 05-03 10:55:46.632  8610  8610 I python.stdout:        32    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
> 05-03 10:55:46.633  8610  8610 I python.stdout:         1    0.000    0.000   12.413   12.413 <string>:1(<module>)
> 05-03 10:55:46.633  8610  8610 I python.stdout:         1    0.000    0.000    0.000    0.000 app.py:469(main_window)
> 05-03 10:55:46.633  8610  8610 I python.stdout:         1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
> 05-03 10:55:46.633  8610  8610 I python.stdout:

[freakboy3742]

Hey @freakboy3742, thanks for the quick response :), I'm developing on windows, but I'm getting same speed when running briefcase dev, as I do when running briefcase android run.

briefcase run vs briefcase dev vs python -m won't make any difference in this case - they're functionally exactly the same. There's only some minor variations in how the Python interpreter is started.

I also have 638 widgets on this window in total, so it might be the process of finding that ID in 638 widgets that is taking sometime (although I thought dict searches were a constant of O(1). Thinking I might need to review how I design my window.

I'd be very surprised if it's dictionary lookup that is the slow portion here. What seems a lot more likely (and is consistent with the profiling trace you've provided) is that you're getting churn in the layout algorithm.

On Windows (and Android as well, IIRC), each update to a widget is applied immediately. When you change the text on a widget, that forces a redraw on the widget, which forces a recalculation of the size of the widget, which causes the layout of the widget to be recomputed, which causes every widget in the layout to be redrawn. Then you update the second label, and the whole redraw cycle starts again. That's obviously a lot of redundancy; and that redundancy manifests as slow update cycles.

The process is slightly more optimised on Cocoa and GTK, because updates are done in batches, so there's less needless recomputes being done. Ideally, we'd be batching these draws on Windows and Android as well; however, as you may be able to imagine, that involves some fairly deep surgery on the lowest levels of the backend implementations. Another approach would be to programmatically allow Toga to temporarily suspend relayouts (say, by wrapping a bunch of updates in a context manager that tracked which widgets had been modified); that would be slightly less invasive, but would require users to opt into the behavior

If you're looking for ways to optimise the redraw right now, my suggestion would be to look at using a table to display this data, rather than hundreds of labels. Table layout is internally optimised by Windows itself, and doesn't trigger the Toga relayout algorithm anywhere near as often. This won't help much on Android at present - the implementation of Table on Android is very primitive, and doesn't have many optimizations - but it should significantly improve performance on Windows.

[BartStolarek]

briefcase run vs briefcase dev vs python -m won't make any difference in this case - they're functionally exactly the same. There's only some minor variations in how the Python interpreter is started.

Sorry i meant to imply that i'm running my app on my android phone, so two platforms windows & android.

I see, when the function is run, the screen does flicker as if its resizing itself constantly. What if I put a static width of the label widgets, and override the force redraw, I don't have the experience to know if this is even possible, but nevertheless your answers have helped me understand the functionality better. Appreciate it!