[Storage][Perfstress] ListBlobs performance regression >20%

[annatisch]

Comparing the listing of large numbers of blobs in T1 vs T2 SDK shows a significant perf regression.
Sync listing in T1 is faster than both sync and async listing in T2.

[mikeharder]

More data:

Scenario	Size	Parallel	Sync	JS	Python
download	10,240	32	async	2,064	2,252
upload	10,240	32	async	2,104	2,500
list-blobs	500	32	async	64	24

Comparing Python to JS, performance is comparable for download and upload, but Python is 60% slower for list-blobs.

[tasherif-msft]

Anna Tisch (@annatisch) Mike Harder (@mikeharder) we are in the process of investigating these regressions!

[mikeharder]

Anna Tisch (@annatisch) Mike Harder (@mikeharder) we are in the process of investigating these regressions!

Tamer (@tasherif-msft): Thanks! It would be great if we could have an update by the April shiproom. Either improving the performance or at least understanding what is causing the slow performance.

During the investigation, keep in mind that the issue might be in azure-core and/or azure-storage-blob.

[tasherif-msft]

Hi Mike Harder (@mikeharder) and Anna Tisch (@annatisch),

After investigating I believe there is not really any substantial regression in blob listing.
I believe the reason we see the regression referenced here is due to the service version. In track 1 we used version '2019-02-02' by default, I think this was unaccounted for in our perf tests. This service version has a several missing payload headers per listed blob since there were not as many features as there is in newer service versions used by T2.

I confirmed this by looking at fiddler traces and profiling the code.
We can see in T1 (with the old service version) the most time consumption:

Blobs listed: 15000
         13730815 function calls (13730725 primitive calls) in 29.916 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1769   20.657    0.012   20.657    0.012 {method 'recv_into' of '_socket.socket' objects}
   510000    1.330    0.000    2.568    0.000 _parser.py:83(get_token)
    30000    1.013    0.000    7.047    0.000 _parser.py:672(_parse)
    90000    0.391    0.000    1.304    0.000 _parser.py:881(_parse_numeric_token)
        3    0.371    0.124    8.902    2.967 _deserialization.py:267(_convert_xml_to_blob_list)
   435230    0.336    0.000    0.336    0.000 {method 'append' of 'list' objects}
        3    0.323    0.108    0.323    0.108 {method 'feed' of 'xml.etree.ElementTree.XMLParser' objects}

You can see that ssl.read() is called 1769 times read the payload for 15,000 blobs through the tunnel.

Looking at T2 with newest service version (2020-04-08):

Blobs listed: 15000
37.558807134628296
         21777521 function calls (21042311 primitive calls) in 37.560 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2065   26.323    0.013   26.323    0.013 {method 'recv_into' of '_socket.socket' objects}
   690024    2.322    0.000    4.024    0.000 serialization.py:1227(xml_key_extractor)
 30021/18    1.440    0.000    9.793    0.544 serialization.py:1358(_deserialize)
  7425500    0.796    0.000    0.796    0.000 {method 'get' of 'dict' objects}
705039/36    0.537    0.000    9.792    0.272 serialization.py:1558(deserialize_data)
   690026    0.446    0.000    0.446    0.000 {method 'split' of 're.Pattern' objects}
    30006    0.406    0.000    1.163    0.000 serialization.py:1448(<setcomp>)
   690018    0.369    0.000    0.369    0.000 {method 'findall' of 'xml.etree.ElementTree.Element' objects}

We can see an approximate 23% regression.
We can see that ssl read is the biggest cause of substantial regression (larger number of calls to read the payload with the same approximate per call cost). After looking at fiddler it was clear that it was due to the payload headers missing in the older service versions (especially when there is large number of blobs - it becomes very evident)

After setting the service version in T1 to match T2 we can see approximately the same performance.
T1:

Blobs listed: 15000
         13734291 function calls (13734201 primitive calls) in 40.487 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2172   29.379    0.014   29.379    0.014 {method 'recv_into' of '_socket.socket' objects}
   510000    1.594    0.000    2.782    0.000 _parser.py:83(get_token)
    30000    1.325    0.000    8.495    0.000 _parser.py:672(_parse)
    90000    0.485    0.000    1.666    0.000 _parser.py:881(_parse_numeric_token)
        3    0.462    0.154   10.810    3.603 _deserialization.py:267(_convert_xml_to_blob_list)
        3    0.374    0.125    0.374    0.125 {method 'feed' of 'xml.etree.ElementTree.XMLParser' objects}

T2:

Blobs listed: 15000
40.000324964523315
         21777916 function calls (21042706 primitive calls) in 40.001 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2144   29.191    0.014   29.191    0.014 {method 'recv_into' of '_socket.socket' objects}
   690024    2.292    0.000    3.969    0.000 serialization.py:1227(xml_key_extractor)
 30021/18    1.383    0.000    9.462    0.526 serialization.py:1358(_deserialize)
  7425500    0.783    0.000    0.783    0.000 {method 'get' of 'dict' objects}
705039/36    0.520    0.000    9.461    0.263 serialization.py:1558(deserialize_data)
   690026    0.424    0.000    0.424    0.000 {method 'split' of 're.Pattern' objects}
    30006    0.384    0.000    1.104    0.000 serialization.py:1448(<setcomp>)
   690018    0.357    0.000    0.357    0.000 {method 'findall' of 'xml.etree.ElementTree.Element' objects}

This is very obvious in this operation in particular since the payload in this operation is huge and depends on the service version.

Let me know if there is anything else that needs to be addressed or if I missed anything. Otherwise we can close this issue :)

Thank you!!