locked
Slow Table Service query preformance RRS feed

  • Question

  • Hi,
    
    Anyone got any idea why the following query could be running so slowly on an Azure storage table? Both the partition key and rowkey are specified, but this query is taking typically 4-6 seconds to complete!
    
    I am doing a lot of these statements in parallel - but across different partitions, so I'd not expect that to cause such a crazy amount of slowdown??
    
       
         
                TableServiceContext context = Utility.StorageAccount.CreateCloudTableClient().GetDataServiceContext();
                DataServiceQuery<BondTickTableEntity> bondTickTable = context.CreateQuery<BondTickTableEntity>("BondTick");
                DateTime validNow = DateTime.UtcNow;
    
                String partitionKey = validNow.ToString(BondTickTableEntity.PARTITION_DATE_FORMAT) + "_" + mBondID;
                String bidRowKey = String.Format("{0}_{1}_True", mTickCurrentBid.PublisherID, mTickCurrentBid.TickID);
                String offerRowKey = String.Format("{0}_{1}_False", mTickCurrentOffer.PublisherID, mTickCurrentOffer.TickID);
                mark(sw, sb);
    
                var prevBondTicks = (from btick in bondTickTable
                                     where btick.PartitionKey == partitionKey
                                     && (btick.RowKey == bidRowKey || btick.RowKey == offerRowKey)
                                     select btick).ToList();
    

    Thanks

    (PS: I tried changing the rowkey so there was no 'OR' statement, i.e. it was literally asking for a specific row, but only got a speed up of <50%

    • Edited by oh8777 Thursday, October 6, 2011 7:58 PM
    Thursday, October 6, 2011 7:56 PM

Answers

  • Hi,

    As mentioned in email it seems the poor performance is caused by additional code added (connect to Service Bus for each request), not the Table storage query itself. I'll close this thread for now. If it's still not resolved please feel free to unmark and reply. I'll follow up.


    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.

    Tuesday, November 15, 2011 8:25 AM

All replies

  • Hi,

    Where are you testing the application? Are you using local storage or cloud storage? You mentioned you’re doing a lot of parallel queries, so if your local machine is not powerful enough, using local storage may slow you down. As for cloud storage, how fast is your network connection? If your network connection is not fast enough, and you’re doing a lot of queries, you may expect some slow down.

    In addition, even if you’re working with different partitions, you’re always making requests to the same domain. By default, you can only open two concurrent connections to a single domain from a client application. Further connections will have to wait until the two connections finishes. You can use ServicePointManager.DefaultConnectionLimit to increase the limit.

     

    Best Regards,

    Ming Xu.


    Please mark the replies as answers if they help or unmark if not.
    If you have any feedback about my replies, please contact msdnmg@microsoft.com.
    Microsoft One Code Framework
    Friday, October 7, 2011 6:25 AM
  • Hi Ming,

     

    Thanks for the reply. I am testing this using Azure storage rather than local. Network connection is 4Mbit/sec, so it should be ok I'd have thought?

    The ServicePointManager.DefaultConnectionLimit is set to 128 - I have max of 16 threads so this shouldn't be coming into play...

     

    Thanks

     

    Friday, October 7, 2011 9:45 AM
  • Update - Have hosted the workers directly on the cloud rather than my own machine, yet still see this query taking ~3000msecs to return.

    I changed the code so that there's only 1 thread running, and this time fell to ~150-250msecs.

    But, this 1 thread is always reading from the same partition. When I had 16 threads, they were each accessing a separate partition at any given time - so the level of contention on a given partition should be the same in both scenarios. Besides which, the published figures for throughput on a single partition are way above this.

    So it looks as though it is some kind of bottleneck in the number of concurrent storage queries that I can run. As mentioned, I have set the ServicePointManager.DefaultConnectionLimit to 128. I do this in the OnStart() method of the RoleEntryPoint class - I tried adding that setting to the actual class doing the updates but it made no difference to performance.

    Anyone got any ideas?

    Thanks 

    Friday, October 7, 2011 11:59 AM
  • Hi,

    From the description it's unlike a storage issue. Most likely it's the coding issue. Could you post more code to show what is returned via:

     TableServiceContext context = Utility.StorageAccount.CreateCloudTableClient().GetDataServiceContext();

    Do you use the same TableServiceContext object or create a new one for each query?

    If it still doesn't work could you send me a repro project? My email is allenc at microsoft.com


    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.


    Wednesday, October 12, 2011 9:16 AM
  • Hi Allen,
    Thanks for the response.
    Utility.StorageAccount is defined as:
            public static CloudStorageAccount StorageAccount
            {
                get
                {
                    if (mStorageAccount == null)
                    {
                        string connectionString = null;
                        try
                        {
                            connectionString = RoleEnvironment.GetConfigurationSettingValue("DataConnectionString");
                        }
                        catch (Exception ex)
                        {
                            Trace.TraceWarning("Could not get storage location setting 'DataConnectionString'.");
                        }
    
                        if (!CloudStorageAccount.TryParse(connectionString, out mStorageAccount))
                            throw TraceThenThrowException("Could not connect to storage account at " + connectionString);
                    }
                    return mStorageAccount;
                }
            }
    

    Where mStorageAccount is a global CloudStorageAccount object.
    Therefore the CloudStorageAccount object is shared across all threads - but the TableServiceContext objects that it creates are created within the individual thread.
    Just to be sure, I replaced the use of the Utility.StorageAccount member within my function with the following .NET API calls:
                string connectionString = RoleEnvironment.GetConfigurationSettingValue("DataConnectionString");
                CloudStorageAccount csa = CloudStorageAccount.Parse(connectionString);
    
    (Then created the context via

    csa.CreateCloudTableClient().GetDataServiceContext();

    )
    But making this change did not make any improvement to the performance.
    Thanks again.
    Wednesday, October 12, 2011 9:58 AM
  • Hi,

    Is my understanding that below code will be executed in all the 16 threads that run at the same time? Could you do below test to narrow down the issue?

    //log thread ID,current time, a string like "Start".

      TableServiceContext context = Utility.StorageAccount.CreateCloudTableClient().GetDataServiceContext();
                DataServiceQuery<BondTickTableEntity> bondTickTable = context.CreateQuery<BondTickTableEntity>("BondTick");
                DateTime validNow = DateTime.UtcNow;

                String partitionKey = validNow.ToString(BondTickTableEntity.PARTITION_DATE_FORMAT) + "_" + mBondID;
                String bidRowKey = String.Format("{0}_{1}_True", mTickCurrentBid.PublisherID, mTickCurrentBid.TickID);
                String offerRowKey = String.Format("{0}_{1}_False", mTickCurrentOffer.PublisherID, mTickCurrentOffer.TickID);
                mark(sw, sb);

    //log thread ID,current time, a string like "BeforeQuery".
                var prevBondTicks = (from btick in bondTickTable
                                     where btick.PartitionKey == partitionKey
                                     && (btick.RowKey == bidRowKey || btick.RowKey == offerRowKey)
                                     select btick).ToList();

    //log thread ID,current time, a string like "End".

    From the logs we probably can get more clues as to what is nottleneck. I guess some stuff is blocking your thread as it's unlike a concurrent HTTP request limitation or a server side issue from the clues given so far. May I also know:

    • What does the mark(sw,sb) do?
    • Do you use any locks or other thread sync code in your app?

    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.





    Thursday, October 13, 2011 8:36 AM
  • Hi Allen,

    Sorry for the delay, got assigned to some other work for a while.

    To answer your 2 questions:

    • mark(sw, sb) is just doing some timing logging, v.similar to what you have asked me to add. However for the latest test I have commented out these calls and added ones as you suggested.
    • There is locking to ensure that only 1 thread is updating a given instrument's price at a given time. i.e. with 16 threads (in a Parallel.For() loop, each one will call bondUpdater[i].updatePrice(). Inside the updatePrice function is a lock(this) command at the beginning to ensure that 2 threads can't update a price simultaneously.

    That's the only locking going on.

     

    In terms of output - I can mail you a s'sheet with the full trace on if you let me know yr email addr, else here's a representative sample...:

    (first item is the bondID, then time, then action)

    [WaWorkerHost.exe] 70 05:10:04.252 Start
    [WaWorkerHost.exe] 70 05:10:04.260 BeforeQuery
    [WaWorkerHost.exe] 18 05:10:04.419 End
    [WaWorkerHost.exe] 28 05:10:04.487 End
    [WaWorkerHost.exe] 72 05:10:04.776 Start
    [WaWorkerHost.exe] 72 05:10:04.783 BeforeQuery
    [WaWorkerHost.exe] 73 05:10:04.811 Start
    [WaWorkerHost.exe] 73 05:10:04.818 BeforeQuery
    [WaWorkerHost.exe] 37 05:10:05.535 End
    [WaWorkerHost.exe] 38 05:10:05.588 End
    [WaWorkerHost.exe] 75 05:10:05.807 Start
    [WaWorkerHost.exe] 75 05:10:05.815 BeforeQuery
    [WaWorkerHost.exe] 76 05:10:05.962 Start
    [WaWorkerHost.exe] 76 05:10:05.970 BeforeQuery
    [WaWorkerHost.exe] 39 05:10:06.137 End
    [WaWorkerHost.exe] 25 05:10:06.206 End
    [WaWorkerHost.exe] 78 05:10:06.392 Start
    [WaWorkerHost.exe] 78 05:10:06.399 BeforeQuery
    [WaWorkerHost.exe] 40 05:10:06.482 End
    [WaWorkerHost.exe] 79 05:10:06.576 Start
    [WaWorkerHost.exe] 79 05:10:06.583 BeforeQuery
    [WaWorkerHost.exe] 81 05:10:06.791 Start
    [WaWorkerHost.exe] 81 05:10:06.798 BeforeQuery
    [WaWorkerHost.exe] 27 05:10:06.832 End
    [WaWorkerHost.exe] 29 05:10:06.992 End
    [WaWorkerHost.exe] 82 05:10:07.261 Start
    [WaWorkerHost.exe] 82 05:10:07.268 BeforeQuery
    [WaWorkerHost.exe] 34 05:10:07.304 End
    [WaWorkerHost.exe] 84 05:10:07.378 Start
    [WaWorkerHost.exe] 84 05:10:07.386 BeforeQuery
    [WaWorkerHost.exe] 86 05:10:07.696 Start
    [WaWorkerHost.exe] 86 05:10:07.704 BeforeQuery
    [WaWorkerHost.exe] 48 05:10:07.987 End
    [WaWorkerHost.exe] 87 05:10:08.342 Start
    [WaWorkerHost.exe] 87 05:10:08.350 BeforeQuery
    [WaWorkerHost.exe] 42 05:10:08.712 End
    [WaWorkerHost.exe] 43 05:10:08.766 End
    [WaWorkerHost.exe] 49 05:10:08.792 End
    [WaWorkerHost.exe] 45 05:10:08.822 End
    [WaWorkerHost.exe] 50 05:10:09.035 End
    [WaWorkerHost.exe] 88 05:10:09.045 Start
    [WaWorkerHost.exe] 88 05:10:09.053 BeforeQuery
    [WaWorkerHost.exe] 89 05:10:09.077 Start
    [WaWorkerHost.exe] 89 05:10:09.092 BeforeQuery
    [WaWorkerHost.exe] 53 05:10:09.097 End
    [WaWorkerHost.exe] 90 05:10:09.136 Start
    [WaWorkerHost.exe] 90 05:10:09.143 BeforeQuery
    [WaWorkerHost.exe] 91 05:10:09.417 Start
    [WaWorkerHost.exe] 91 05:10:09.425 BeforeQuery
    [WaWorkerHost.exe] 92 05:10:09.485 Start
    [WaWorkerHost.exe] 92 05:10:09.493 BeforeQuery
    [WaWorkerHost.exe] 54 05:10:09.585 End
    [WaWorkerHost.exe] 93 05:10:09.774 Start
    [WaWorkerHost.exe] 93 05:10:09.781 BeforeQuery
    [WaWorkerHost.exe] 56 05:10:10.393 End
    [WaWorkerHost.exe] 94 05:10:10.656 Start
    [WaWorkerHost.exe] 94 05:10:10.664 BeforeQuery
    [WaWorkerHost.exe] 95 05:10:10.707 Start
    [WaWorkerHost.exe] 95 05:10:10.714 BeforeQuery
    [WaWorkerHost.exe] 52 05:10:11.216 End
    [WaWorkerHost.exe] 58 05:10:11.288 End
    [WaWorkerHost.exe] 61 05:10:11.343 End
    [WaWorkerHost.exe] 96 05:10:11.512 Start
    [WaWorkerHost.exe] 96 05:10:11.520 BeforeQuery
    [WaWorkerHost.exe] 97 05:10:11.709 Start
    [WaWorkerHost.exe] 97 05:10:11.716 BeforeQuery
    [WaWorkerHost.exe] 98 05:10:11.772 Start
    [WaWorkerHost.exe] 98 05:10:11.779 BeforeQuery
    [WaWorkerHost.exe] 55 05:10:11.943 End
    [WaWorkerHost.exe] 62 05:10:12.119 End
    [WaWorkerHost.exe] 99 05:10:12.415 Start
    [WaWorkerHost.exe] 99 05:10:12.422 BeforeQuery
    [WaWorkerHost.exe] 100 05:10:12.469 Start
    [WaWorkerHost.exe] 100 05:10:12.476 BeforeQuery
    [WaWorkerHost.exe] 57 05:10:12.503 End
    [WaWorkerHost.exe] 1 05:10:12.762 Start
    [WaWorkerHost.exe] 1 05:10:12.769 BeforeQuery
    [WaWorkerHost.exe] 65 05:10:12.789 End
    [WaWorkerHost.exe] 60 05:10:13.003 End
    [WaWorkerHost.exe] 2 05:10:13.051 Start
    [WaWorkerHost.exe] 2 05:10:13.059 BeforeQuery
    [WaWorkerHost.exe] 3 05:10:13.259 Start
    [WaWorkerHost.exe] 3 05:10:13.267 BeforeQuery
    [WaWorkerHost.exe] 67 05:10:13.488 End
    [WaWorkerHost.exe] 63 05:10:13.755 End
    [WaWorkerHost.exe] 4 05:10:13.778 Start
    [WaWorkerHost.exe] 4 05:10:13.785 BeforeQuery
    [WaWorkerHost.exe] 64 05:10:14.073 End
    [WaWorkerHost.exe] 5 05:10:14.081 Start
    [WaWorkerHost.exe] 5 05:10:14.088 BeforeQuery
    [WaWorkerHost.exe] 70 05:10:14.183 End
    [WaWorkerHost.exe] 6 05:10:14.414 Start
    [WaWorkerHost.exe] 6 05:10:14.422 BeforeQuery
    [WaWorkerHost.exe] 7 05:10:14.689 Start
    [WaWorkerHost.exe] 7 05:10:14.696 BeforeQuery
    [WaWorkerHost.exe] 69 05:10:14.924 End
    [WaWorkerHost.exe] 73 05:10:15.083 End
    [WaWorkerHost.exe] 8 05:10:15.339 Start
    [WaWorkerHost.exe] 8 05:10:15.346 BeforeQuery
    [WaWorkerHost.exe] 9 05:10:15.652 Start
    [WaWorkerHost.exe] 9 05:10:15.660 BeforeQuery
    [WaWorkerHost.exe] 75 05:10:15.904 End
    [WaWorkerHost.exe] 72 05:10:16.078 End
    [WaWorkerHost.exe] 76 05:10:16.213 End
    [WaWorkerHost.exe] 10 05:10:16.246 Start
    [WaWorkerHost.exe] 10 05:10:16.253 BeforeQuery
    [WaWorkerHost.exe] 78 05:10:16.403 End
    [WaWorkerHost.exe] 11 05:10:16.444 Start
    [WaWorkerHost.exe] 11 05:10:16.451 BeforeQuery
    [WaWorkerHost.exe] 81 05:10:16.459 End
    [WaWorkerHost.exe] 12 05:10:16.656 Start
    [WaWorkerHost.exe] 12 05:10:16.664 BeforeQuery
    [WaWorkerHost.exe] 13 05:10:16.712 Start
    [WaWorkerHost.exe] 13 05:10:16.719 BeforeQuery
    [WaWorkerHost.exe] 82 05:10:16.979 End
    [WaWorkerHost.exe] 14 05:10:17.104 Start
    [WaWorkerHost.exe] 14 05:10:17.112 BeforeQuery
    [WaWorkerHost.exe] 15 05:10:17.252 Start
    [WaWorkerHost.exe] 15 05:10:17.259 BeforeQuery
    [WaWorkerHost.exe] 86 05:10:17.527 End
    [WaWorkerHost.exe] 79 05:10:17.873 End
    [WaWorkerHost.exe] 16 05:10:17.964 Start
    [WaWorkerHost.exe] 16 05:10:17.971 BeforeQuery
    [WaWorkerHost.exe] 17 05:10:18.363 Start
    [WaWorkerHost.exe] 17 05:10:18.370 BeforeQuery
    [WaWorkerHost.exe] 87 05:10:18.387 End
    [WaWorkerHost.exe] 18 05:10:18.894 Start
    [WaWorkerHost.exe] 18 05:10:18.901 BeforeQuery
    [WaWorkerHost.exe] 84 05:10:19.122 End
    [WaWorkerHost.exe] 88 05:10:19.188 End
    [WaWorkerHost.exe] 89 05:10:19.243 End
    [WaWorkerHost.exe] 19 05:10:19.448 Start
    [WaWorkerHost.exe] 19 05:10:19.457 BeforeQuery
    [WaWorkerHost.exe] 20 05:10:19.494 Start
    [WaWorkerHost.exe] 20 05:10:19.503 BeforeQuery
    [WaWorkerHost.exe] 21 05:10:19.512 Start
    [WaWorkerHost.exe] 21 05:10:19.521 BeforeQuery
    [WaWorkerHost.exe] 90 05:10:21.615 End
    [WaWorkerHost.exe] 91 05:10:21.757 End
    [WaWorkerHost.exe] 92 05:10:21.810 End
    [WaWorkerHost.exe] 93 05:10:21.864 End
    [WaWorkerHost.exe] 94 05:10:21.890 End
    [WaWorkerHost.exe] 23 05:10:21.982 Start
    [WaWorkerHost.exe] 23 05:10:21.989 BeforeQuery
    [WaWorkerHost.exe] 24 05:10:22.040 Start
    [WaWorkerHost.exe] 24 05:10:22.048 BeforeQuery
    [WaWorkerHost.exe] 25 05:10:22.126 Start
    [WaWorkerHost.exe] 26 05:10:22.126 Start
    [WaWorkerHost.exe] 25 05:10:22.134 BeforeQuery
    [WaWorkerHost.exe] 26 05:10:22.141 BeforeQuery
    [WaWorkerHost.exe] 27 05:10:22.172 Start
    [WaWorkerHost.exe] 27 05:10:22.180 BeforeQuery
    [WaWorkerHost.exe] 95 05:10:22.917 End
    [WaWorkerHost.exe] 96 05:10:23.284 End
    [WaWorkerHost.exe] 97 05:10:23.444 End
    [WaWorkerHost.exe] 98 05:10:23.499 End
    [WaWorkerHost.exe] 28 05:10:23.526 Start
    [WaWorkerHost.exe] 28 05:10:23.533 BeforeQuery
    [WaWorkerHost.exe] 29 05:10:23.789 Start
    [WaWorkerHost.exe] 29 05:10:23.795 BeforeQuery
    [WaWorkerHost.exe] 34 05:10:23.823 Start
    [WaWorkerHost.exe] 34 05:10:23.830 BeforeQuery
    [WaWorkerHost.exe] 100 05:10:23.990 End
    [WaWorkerHost.exe] 37 05:10:24.053 Start
    [WaWorkerHost.exe] 37 05:10:24.063 BeforeQuery
    [WaWorkerHost.exe] 1 05:10:24.292 End
    [WaWorkerHost.exe] 38 05:10:24.338 Start
    [WaWorkerHost.exe] 38 05:10:24.346 BeforeQuery
    [WaWorkerHost.exe] 99 05:10:24.386 End
    [WaWorkerHost.exe] 39 05:10:24.608 Start
    [WaWorkerHost.exe] 39 05:10:24.618 BeforeQuery
    [WaWorkerHost.exe] 2 05:10:24.807 End
    [WaWorkerHost.exe] 40 05:10:24.827 Start
    [WaWorkerHost.exe] 40 05:10:24.834 BeforeQuery
    [WaWorkerHost.exe] 42 05:10:25.056 Start
    [WaWorkerHost.exe] 42 05:10:25.064 BeforeQuery
    [WaWorkerHost.exe] 3 05:10:25.325 End
    [WaWorkerHost.exe] 43 05:10:25.667 Start
    [WaWorkerHost.exe] 43 05:10:25.675 BeforeQuery
    [WaWorkerHost.exe] 4 05:10:25.946 End
    [WaWorkerHost.exe] 45 05:10:26.309 Start
    [WaWorkerHost.exe] 45 05:10:26.316 BeforeQuery
    [WaWorkerHost.exe] 6 05:10:26.384 End
    [WaWorkerHost.exe] 5 05:10:26.417 End
    [WaWorkerHost.exe] 48 05:10:26.696 Start
    [WaWorkerHost.exe] 48 05:10:26.704 BeforeQuery
    [WaWorkerHost.exe] 49 05:10:26.768 Start
    [WaWorkerHost.exe] 49 05:10:26.776 BeforeQuery
    [WaWorkerHost.exe] 8 05:10:26.894 End
    [WaWorkerHost.exe] 7 05:10:27.013 End
    [WaWorkerHost.exe] 9 05:10:27.230 End
    [WaWorkerHost.exe] 50 05:10:27.293 Start
    [WaWorkerHost.exe] 50 05:10:27.300 BeforeQuery
    [WaWorkerHost.exe] 52 05:10:27.325 Start
    [WaWorkerHost.exe] 52 05:10:27.334 BeforeQuery
    [WaWorkerHost.exe] 10 05:10:27.560 End
    [WaWorkerHost.exe] 53 05:10:27.653 Start
    [WaWorkerHost.exe] 53 05:10:27.661 BeforeQuery
    [WaWorkerHost.exe] 54 05:10:27.878 Start
    [WaWorkerHost.exe] 54 05:10:27.886 BeforeQuery
    [WaWorkerHost.exe] 11 05:10:27.954 End
    [WaWorkerHost.exe] 55 05:10:28.318 Start
    [WaWorkerHost.exe] 55 05:10:28.325 BeforeQuery
    [WaWorkerHost.exe] 13 05:10:28.485 End
    [WaWorkerHost.exe] 12 05:10:28.528 End
    [WaWorkerHost.exe] 14 05:10:28.540 End
    [WaWorkerHost.exe] 56 05:10:28.853 Start
    [WaWorkerHost.exe] 56 05:10:28.862 BeforeQuery
    [WaWorkerHost.exe] 57 05:10:28.878 Start
    [WaWorkerHost.exe] 57 05:10:28.885 BeforeQuery
    [WaWorkerHost.exe] 58 05:10:28.946 Start
    [WaWorkerHost.exe] 58 05:10:28.953 BeforeQuery
    [WaWorkerHost.exe] 15 05:10:29.175 End
    [WaWorkerHost.exe] 60 05:10:29.596 Start
    [WaWorkerHost.exe] 60 05:10:29.603 BeforeQuery
    [WaWorkerHost.exe] 16 05:10:29.900 End
    [WaWorkerHost.exe] 17 05:10:30.010 End
    [WaWorkerHost.exe] 61 05:10:30.214 Start
    [WaWorkerHost.exe] 61 05:10:30.222 BeforeQuery
    [WaWorkerHost.exe] 62 05:10:30.266 Start
    [WaWorkerHost.exe] 62 05:10:30.273 BeforeQuery
    [WaWorkerHost.exe] 18 05:10:30.788 End
    [WaWorkerHost.exe] 63 05:10:31.089 Start
    [WaWorkerHost.exe] 63 05:10:31.096 BeforeQuery
    [WaWorkerHost.exe] 20 05:10:31.117 End
    [WaWorkerHost.exe] 21 05:10:31.175 End
    [WaWorkerHost.exe] 64 05:10:31.479 Start
    [WaWorkerHost.exe] 64 05:10:31.487 BeforeQuery
    [WaWorkerHost.exe] 65 05:10:31.527 Start
    [WaWorkerHost.exe] 65 05:10:31.535 BeforeQuery
    [WaWorkerHost.exe] 19 05:10:31.643 End
    [Diagnostics]: Checking for configuration updates 18/10/2011 18:37:31.
    [WaWorkerHost.exe] 67 05:10:32.054 Start
    [WaWorkerHost.exe] 67 05:10:32.062 BeforeQuery
    [WaWorkerHost.exe] 24 05:10:32.711 End

    Thanks again for any suggestions

    Oli

     

    Tuesday, October 18, 2011 5:39 PM
  • Hi,

    Thanks for your reply. A question, why there're >16 "Start"s in the log? Do you really use 16 threads?

    From the log it seems there is some code executed before the code you posted stops the thread to execute your posted code. And it seems some code after your posted code can release it. As you can see, the thread 67 begins to execute your posted code 28 seconds after thread 70 begins to execute your code. What happens if you replace your posted code with:

    //log thread ID,current time, a string like "Start"

    //Thread.Sleep(2000);

    If you can see the same behavior it confirms my guess that it's not related to Azure.

    So please first double check your code, if there is nothing special, read below.

    I just tested Parallel.For and found it has similar problem with ThreadPool.QueueUserWorkItem. Both of them will reuse threads, etc. Obviously such kind of features may consume more time than using ThreadStart&Thread to execute code directly. (I seldom use Task Parallel library so cannot comment much on this) Below is what I tested:

    class Program

        {

            static void Main(string[] args)

            {

      //Parallel.For(0, 16, (i) => { Console.WriteLine(DateTime.Now.ToString() + Thread.CurrentThread.ManagedThreadId); Thread.Sleep(4000); });

                for (int i = 0; i < 16; i++)

                {

                    ThreadStart ts = new ThreadStart(() => { Console.WriteLine(DateTime.Now.ToString() + Thread.CurrentThread.ManagedThreadId); Thread.Sleep(4000); });

                    Thread t = new Thread(ts);

                    t.Start();

     

                }

     

                Console.ReadLine();

            }

        }

     

    By comparing two results you will see significant performance issue.

    Please let me know whether this is the cause of the problem. If it's not feel free to send me a repro project. My email is allenc at microsoft.com.

     

    BTW, it's suggested to avoid using lock(this) in your code as it may involve potential problems such as deadlock. The correct way to use lock is to add a private field A and use lock(instanceoffieldA) for object level lock or add a static private field B and use lock(instanceoffieldB) for type level lock.

     


    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.






    Wednesday, October 19, 2011 2:46 AM
  • Hi Allen,

    Sorry if my log post caused some confusion. It is just a randomly selected subsample of the overall log trace. There are only 16 threads running in parallel, but they run in an infinite loop - hence you see >16 'Start' statements in the log.

    The parallel.for loop loops through a list of bondIDs (let's say 1-100), updating the price of each in turn. When ID 100 is reached, the next thread to start begins again from ID 0, and so on.

    I don't quite understand what you mean by replacing the table query section of code with:

    Thread.Sleep(2000);

    Surely then it'll just take 2000 msecs (+/-) to go from the 'Start' statement to the 'BeforeQuery' one? Not sure what this would prove? 

    Seems to me that, if you look at one bondID in isolation (let's say 70, the first one from the sample trace above):

    [WaWorkerHost.exe] 70 05:10:04.252 Start
    [WaWorkerHost.exe] 70 05:10:04.260 BeforeQuery

    then a big gap in which other threads are running, then....

    [WaWorkerHost.exe] 70 05:10:14.183 End

    i.e. almost 10 seconds elapsed while executing the following code:

                Trace.TraceInformation("{0}\t{1}\tBeforeQuery", mBondID, DateTime.UtcNow.ToString("hh:MM:ss.fff")); 
                var prevBondTicks = (from btick in bondTickTable
                                     where btick.PartitionKey == partitionKey
                                     && (btick.RowKey == bidRowKey || btick.RowKey == offerRowKey)
                                     select btick).ToList();
                //mark(sw, sb);
                Trace.TraceInformation("{0}\t{1}\tEnd", mBondID, DateTime.UtcNow.ToString("hh:MM:ss.fff"));
    


    (All the other bondIDs show similar timings).

    Seems to me that the only explanation for this can be that the query is running slowly when accessed via many threads at once (this example is even slower than usual - in actual fact I had 32 threads in parallel on this occasion).

     

    I will send via email a full log trace from another test run, along with a stripped-down version of the project w instructions. Thanks again for your help on this.

    Oli

     

     

     

     

    Thursday, October 20, 2011 1:14 PM
  • I would surgest you use fiddler maybe to ensure 16 are executing at once if they really are taking 3000ms then you should see 16 request awaiting a result in fiddler.
    Friday, October 21, 2011 1:56 PM
  • I would surgest you use fiddler maybe to ensure 16 are executing at once if they really are taking 3000ms then you should see 16 request awaiting a result in fiddler.


    Yes this is a good way to narrow down this issue. I have got a project from Dream Walker and below is some quote from my reply email. The max request time for the 16 calls to finish is about 6 seconds in my test .

     I tried to simplify your application using a simple Console application. Below is my test code:

     

    namespace TestApp

    {

        class Program

        {

         

            static void Main(string[] args)

            {

     

                Test test = new Test();

                while (true)

                {

                    test.Run();

                    Console.ReadLine();

                }

            

               

            }

            public class Test

            {

                static Random r = new Random();

                public void Run()

                {

    // You can change thread num to 1. It turns out that thread num doesnt change anything based on my test.

                    int maxThreads = 32;

     

                    ServicePointManager.DefaultConnectionLimit = 128;

     

                    for (int i = 0; i < maxThreads; i++)

                    {

     

                        ThreadStart ts = new ThreadStart(() =>

                        {

                            CodeToTroubleshoot();

     

                        });

     

                        Thread t = new Thread(ts);

     

                        t.Start();

     

     

     

                    }

     

                    //Parallel.For(0, 32, ignored =>

                    //{

     

                    //    CodeToTroubleshoot();

                    //});

     

                }

                private void CodeToTroubleshoot()

                {

                    var mBondID = getNextBondIDToUpdate();

                    Stopwatch sw = new Stopwatch();

                    Debug.WriteLine("{0}\t{1}\tStart ", mBondID, DateTime.UtcNow.ToString("HH:mm:ss.fff"));

     

     

     

                    TableServiceContext context = Utility.StorageAccount.CreateCloudTableClient().GetDataServiceContext();

                    DataServiceQuery<BondTickTableEntity> bondTickTable = context.CreateQuery<BondTickTableEntity>("BondTick");

                    DateTime validNow = DateTime.UtcNow;

     

                    String partitionKey = validNow.ToString("removed as it may contain privacy data" + mBondID);

                    String bidRowKey = String.Format("{0}_{1}_True", r.Next(1, 1000000), r.Next(1, 1000000));

                    //String offerRowKey = String.Format("{0}_{1}_False", r.Next(1, 1000000), r.Next(1, 1000000));

     

                    //String bidRowKey = "removed as it may contain privacy data";

                    String offerRowKey = "removed as it may contain privacy data";

     

                 

                    sw.Start();

                    var prevBondTicks = (from btick in bondTickTable

                                          where btick.PartitionKey == partitionKey

                                           && (btick.RowKey == bidRowKey || btick.RowKey == offerRowKey)

                                         select btick).ToList();

     

                    sw.Stop();

                   

                    Debug.WriteLine("{0}\telapsed:{1}\tEnd ", mBondID, sw.Elapsed);

                }

                int num=0;

                private int getNextBondIDToUpdate()

                {

                    num++;

                    return num;

                }

     

            

            }

       

        }

     

    }

     

     

    Below is a Fiddler log (I used HTTP connection to test) when I run the above test code:

     

    When there is no matched entity returned:

     

    ClientConnected:     02:11:43.556

    ClientBeginRequest:  02:11:43.556

    ClientDoneRequest:   02:11:43.556

    Determine Gateway:   31ms

    DNS Lookup:          0ms

    TCP/IP Connect:      0ms

    HTTPS Handshake:     0ms

    ServerConnected:     02:11:41.985

    FiddlerBeginRequest: 02:11:43.583

    ServerGotRequest:    02:11:43.584

    ServerBeginResponse: 02:11:43.977

    ServerDoneResponse:  02:11:43.977

    ClientBeginResponse: 02:11:43.977

    ClientDoneResponse:  02:11:43.977

     

           Overall Elapsed:     00:00:00.4203360

     

    When there is 1 matched  entity returned:

     

     

    ClientConnected:     02:18:11.787

    ClientBeginRequest:  02:18:11.787

    ClientDoneRequest:   02:18:11.787

    Determine Gateway:   63ms

    DNS Lookup:          0ms

    TCP/IP Connect:      85ms

    HTTPS Handshake:     0ms

    ServerConnected:     02:18:11.940

    FiddlerBeginRequest: 02:18:11.940

    ServerGotRequest:    02:18:11.940

    ServerBeginResponse: 02:18:13.046

    ServerDoneResponse:  02:18:13.046

    ClientBeginResponse: 02:18:13.046

    ClientDoneResponse:  02:18:13.046

     

           Overall Elapsed:     00:00:01.2590064

     

    It seems reasonable data. I cannot reproduce the 10 seconds request time however. Could you try my demo and let me know how to reproduce it? The time elapsed should mainly contain:

     

    1.       Time to execute code in Data service client library. Including serialization time (not in your case as you just send a simple GET)

    2.       DNS look up, TCP/IP connection, HTTPS handshake, etc.

    3.       Request data transfer time.

    4.       Time for server to handle request.

    5.       Response data transfer time.

    6.       Time to execute code in Data service client library. Including deserialization time

     

    When I use HTTPS it will take more time. From the given clues so far the bottleneck seems to be the Data Service client and I guess it’s mainly caused by deserialization work. If that’s the case a possible way to improve performance is to write raw HTTP request code and parse response in a better manner instead of using Data Service client.

     

    Please let me know your test result.

     


    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.


    Monday, October 24, 2011 7:30 AM
  • Hi,

    [Have emailed Allen separately, with example project, but thought I'd post here too in case someone has seen similar behaviour]

     

    I took Allen's latest test code above, and ran it in a console app - and saw dramatically faster table access (10x quicker).

    So - I thought that it must have been some of the extra code that I had in my original program that was causing the slowdown.

    Taking his console app as my base, I added functionality back in bit by bit. I was able to add back in ALL the code without the performance degrading.

    Weird.

    OK, so next I made a couple of minor, minor adaptations (things like passing in config from the RoleManager rather than hard coding, and logging to Trace rather than the console), so that I could run the same code from either Azure, or the console, just by changing which was the Solution's startup project.

    When running this in the console - I got the same improved performance as before.

    When running in the Azure emulator (still accessing same 'proper' storage acct though) - 10x slower table access times.

     

    So now I am running identical code, yet see a gulf in the table access performance when running via the azure emulator.

    Has anyone seen anything similar or got any idea as to why this might be happening?

    (NB: Realise that additional processes are running on my machine when I run this via the emulator - however I released the code onto the cloud proper, and got similar results there too, i.e. v.slow table access. In any case you wouldn't expect the difference to be anywhere near so large?)

     

    Thanks

    Wednesday, October 26, 2011 9:47 AM
  • Update:

    It seems is not a emulator issue but caused by additional code. Will post more information here if the cause is found.


    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.

    Friday, October 28, 2011 9:32 AM
  • Hi,

    As mentioned in email it seems the poor performance is caused by additional code added (connect to Service Bus for each request), not the Table storage query itself. I'll close this thread for now. If it's still not resolved please feel free to unmark and reply. I'll follow up.


    Allen Chen [MSFT]
    MSDN Community Support | Feedback to us
    Get or Request Code Sample from Microsoft
    Please remember to mark the replies as answers if they help and unmark them if they provide no help.

    Tuesday, November 15, 2011 8:25 AM