Analyze Table Storage queries locally

In general Table Storage has this awesome feature to check what kind of heresy we're creating by turning on diagnostics logs in the portal. It allows us to analyze queries and operations, so it's possible to find potentially problematic places and tweak them with ease. This functionality has one major drawback - we have to actually deploy our application and run it in the cloud. 

For most of the time you'll be developing using Table Storage Emulator. It'd great to check all our queries right after developing a feature. What options do we have? In fact Emulator has its own logs - they won't be as good and smooth as with full diagnostics, but for most scenarios they should be sufficient.

In the portal we have plenty of options we can use to analyze Table Storage performance

Enabling logging locally

To enable logging, you have to rutn this feature on in the Emulator config. You can find it located here:

C:\Users\{USER}\AppData\Local\AzureStorageEmulator

My config looks like this:

/
<?xml version="1.0"?>
<StorageEmulator xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <SQLInstance>(localdb)\MSSQLLocalDB</SQLInstance>
  <PageBlobRoot>C:\Users\kamz\AppData\Local\AzureStorageEmulator\PageBlobRoot</PageBlobRoot>
  <BlockBlobRoot>C:\Users\kamz\AppData\Local\AzureStorageEmulator\BlockBlobRoot</BlockBlobRoot>
  <LogPath>C:\Users\kamz\AppData\Local\AzureStorageEmulator\Logs</LogPath>
  <LoggingEnabled>false</LoggingEnabled>
</StorageEmulator>

To turn logging on you have to change LoggingEnabled property to true. If you have Emulator running, you'll have to restart it.

Reading logs

Once logging is enabled you'll see, that in the following location:

C:\Users\{USER}\AppData\Local\AzureStorageEmulator\Logs

Some files are starting to appear. There're logs with different levels of severity + some performance related information. If everything's running smoothly most of those files won't be helpful for you. In my scenario I find Verbose_debug file most interesting. 

This file contains information about requests which are handled by our Emulator. Consider following log:

/
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] Got request GET http://127.0.0.1:10002/devstoreaccount1/Tables('User') 2015-12-11
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] Host-style URI resolution failed. Allowing path-style for uri http://127.0.0.1:10002/devstoreaccount1/Tables('User')
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] StorageAccount.GetPropertiesImpl(PropertyNames=0x0020, ServiceMetadataPropertyNames=0x000000007807C000,,00:00:30)
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] Setting status code to 200
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] In the process end callback
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] Entering BasicHttpRestProcessor.EndProcess
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=c7a80f0d-4c22-4cdf-bfc2-89b983d5a363] Leaving concurrent request: 0
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] Entering concurrent request: 1
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] Got request GET http://127.0.0.1:10002/devstoreaccount1/Tables('UserXCompany') 2015-12-11
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] Host-style URI resolution failed. Allowing path-style for uri http://127.0.0.1:10002/devstoreaccount1/Tables('UserXCompany')
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] StorageAccount.GetPropertiesImpl(PropertyNames=0x0020, ServiceMetadataPropertyNames=0x000000007807C000,,00:00:30)
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] Setting status code to 200
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] In the process end callback
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] Entering BasicHttpRestProcessor.EndProcess
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=2131ae3e-cee7-4bbd-a2b9-2ab795dfb60e] Leaving concurrent request: 0
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] Entering concurrent request: 1
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] Got request GET http://127.0.0.1:10002/devstoreaccount1/Tables('Company') 2015-12-11
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] Host-style URI resolution failed. Allowing path-style for uri http://127.0.0.1:10002/devstoreaccount1/Tables('Company')
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] StorageAccount.GetPropertiesImpl(PropertyNames=0x0020, ServiceMetadataPropertyNames=0x000000007807C000,,00:00:30)
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] Setting status code to 200
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] In the process end callback
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] Entering BasicHttpRestProcessor.EndProcess
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=93d3b264-e4b1-4233-950f-225c7756ee14] Leaving concurrent request: 0
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Entering concurrent request: 1
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Got request GET http://127.0.0.1:10002/devstoreaccount1/User?$top=20 2015-12-11
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Host-style URI resolution failed. Allowing path-style for uri http://127.0.0.1:10002/devstoreaccount1/User?$top=20
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] StorageAccount.GetPropertiesImpl(PropertyNames=0x0020, ServiceMetadataPropertyNames=0x000000007807C000,,00:00:30)
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Setting status code to 200
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] In the process end callback
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Entering BasicHttpRestProcessor.EndProcess
16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Leaving concurrent request: 0
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Entering concurrent request: 1
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Got request GET http://127.0.0.1:10002/devstoreaccount1/UserXCompany?$filter=PartitionKey%20eq%20%27b55cf6d6-0012-480d-a792-9d4bb0813431%27 2015-12-11
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Host-style URI resolution failed. Allowing path-style for uri http://127.0.0.1:10002/devstoreaccount1/UserXCompany?$filter=PartitionKey%20eq%20%27b55cf6d6-0012-480d-a792-9d4bb0813431%27
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] StorageAccount.GetPropertiesImpl(PropertyNames=0x0020, ServiceMetadataPropertyNames=0x000000007807C000,,00:00:30)
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Setting status code to 200
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] In the process end callback
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Entering BasicHttpRestProcessor.EndProcess
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Leaving concurrent request: 0
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Entering concurrent request: 1
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Got request GET http://127.0.0.1:10002/devstoreaccount1/Company?$filter=RowKey%20eq%20%272de37ce9-b012-43f9-9c09-ba1107bddaaf%27&$top=1 2015-12-11
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Host-style URI resolution failed. Allowing path-style for uri http://127.0.0.1:10002/devstoreaccount1/Company?$filter=RowKey%20eq%20%272de37ce9-b012-43f9-9c09-ba1107bddaaf%27&$top=1
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] StorageAccount.GetPropertiesImpl(PropertyNames=0x0020, ServiceMetadataPropertyNames=0x000000007807C000,,00:00:30)
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Setting status code to 200
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] In the process end callback
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Entering BasicHttpRestProcessor.EndProcess
16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Leaving concurrent request: 0

There're many information which we can get from it:

  • How many operations were handled during our queries
  • Which operations were handled concurrently
  • Which tables were queries
  • What queries were used to obtain information

Let's check how it related to the real function. Above log was generated for the following function:

/
[FunctionName("UserList")]
public static Task<HttpResponseMessage> UserList(
	[HttpTrigger(AuthorizationLevel.Anonymous, "get", Route = "user")] HttpRequestMessage req,
	[Table("User", "AzureWebJobsStorage")] IQueryable<UserEntity> users,
	[Table("UserXCompany", "AzureWebJobsStorage")] IQueryable<UserXCompanyEntity> usersXCompanies,
	[Table("Company", "AzureWebJobsStorage")] IQueryable<Company.CompanyEntity> companies,
	TraceWriter log)
{
	var usersQuery = users.Take(20).ToList().Select(_ => new
	{
		Login = _.Login,
		Name = _.Name,
		Surname = _.Surname,
		Company = FindUserCompanies(_, usersXCompanies, companies)
	});

	var response = req.CreateResponse(HttpStatusCode.OK,
		usersQuery);

	return Task.FromResult(response);
}

private static List<string> FindUserCompanies(UserEntity user, IQueryable<UserXCompanyEntity> usersXCompanies,
	IQueryable<Company.CompanyEntity> companies)
{
	var values = usersXCompanies.Where(_ => _.PartitionKey == user.RowKey).ToList();
	return values.Select(value => companies.Where(_ => _.RowKey == value.RowKey).First().Name).ToList();
}

I was expecting to see 3 queries(per each User loaded). Note that those queries were created dynamically thanks to using IQueryable<>:

  • GET 'User', TOP 20
  • GET 'UserXCompany', PartitionKey = User.RowKey
  • GET 'Company', TOP 1, RowKey = UserXCompany.RowKey

Did I get them?

16.02.2018 22:13:16 [Verbose_debug] [ActivityId=eba444dc-2752-4d92-a993-a96f4b8ab771] Got request GET http://127.0.0.1:10002/devstoreaccount1/User?$top=20 2015-12-11

16.02.2018 22:13:17 [Verbose_debug] [ActivityId=e08f0361-1901-493f-b1cc-885d8a3fd6d8] Got request GET http://127.0.0.1:10002/devstoreaccount1/UserXCompany?$filter=PartitionKey%20eq%20%27b55cf6d6-0012-480d-a792-9d4bb0813431%27 2015-12-11

16.02.2018 22:13:17 [Verbose_debug] [ActivityId=11f9e8e6-f345-4a65-8221-0be27c9edbaa] Got request GET http://127.0.0.1:10002/devstoreaccount1/Company?$filter=RowKey%20eq%20%272de37ce9-b012-43f9-9c09-ba1107bddaaf%27&$top=1 2015-12-11

What now?

Now when I'm able to see how it looks under the hood I'm both confident, that the code I wrote works as expected and I'm able to tweak queries if I must. Maybe I should store Company information with a User to save one query? Maybe I should limit UserXCompany rows fetched? There many possibilities but once you're ready for changes, things should be easier in the future.

 

 

Don't "admin" me!

This was somehow unexpected. I was flawlessly developing my API using Azure Functions and then BANG! - suddenly my functions are in error state. Just like that - no stack trace, no detailed explanation. I took me some time to realize, that they all have one thing in common - they share the admin part. Apparently Functions have some problems when you're using HttpTrigger with a custom route containg admin word. What is the reason?

Check the codebase

Let's take a quick look at the codebase of Functions. Finding a place, which causes the error is pretty simple:

/
internal static void ValidateHttpFunction(string functionName, HttpTriggerAttribute httpTrigger, bool isProxy = false)
{
	if (string.IsNullOrWhiteSpace(httpTrigger.Route) && !isProxy)
	{
		// if no explicit route is provided, default to the function name
		httpTrigger.Route = functionName;
	}

	// disallow custom routes in our own reserved route space
	string httpRoute = httpTrigger.Route.Trim('/').ToLowerInvariant();
	if (httpRoute.StartsWith("admin"))
	{
		throw new InvalidOperationException("The specified route conflicts with one or more built in routes.");
	}
}

As you can see, all routes which start with admin are disallowed. While this is perfectly fine, I couldn't find any mention in the documentation, which would clarify this. 

When in doubt always try to check the source. Some answers will be quite difficult to obtain, but you'll end up with a much better overall understanding of the library. The rest will be rather straightforward, nothing you can't handle, isn't it?