Turns out I’m not very good at blogging very often. However I thought I would put what I’ve been working on for the last few days here out of interest.

For a while the OpenStack Infrastructure team have wanted to move away from storing logs on disk to something more cloudy – namely, swift. I’ve been working on this on and off for a while and we’re nearly there.

For the last few weeks the openstack-infra/project-config repository has been uploading its CI test logs to swift as well as storing them on disk. This has given us the opportunity to compare the last few weeks of data and see what kind of effects we can expect as we move assets into an object storage.

• I should add a disclaimer/warning, before you read, that my methods here will likely make statisticians cringe horribly. For the moment though I’m just getting an indication for how things compare.

The set up

Fetching files from an object storage is nothing particularly new or special (CDN’s have been doing it for ages). However, for our usage we want to serve logs with os-loganalyze giving the opportunity to hyperlink to timestamp anchors or filter by log severity.

First though we need to get the logs into swift somehow. This is done by having the job upload its own logs. Rather than using (or writing) a Jenkins publisher we use a bash script to grab the jobs own console log (pulled from the Jenkins web ui) and then upload it to swift using credentials supplied to the job as environment variables (see my zuul-swift contributions).

This does, however, mean part of the logs are missing. For example the fetching and upload processes write to Jenkins’ console log but because it has already been fetched these entries are missing. Therefore this wants to be the very last thing you do in a job. I did see somebody do something similar where they keep the download process running in a fork so that they can fetch the full log but we’ll look at that another time.

When a request comes into logs.openstack.org, a request is handled like so:

1. apache vhost matches the server
2. if the request ends in .txt.gz, console.html or console.html.gz rewrite the url to prepend /htmlify/
3. if the requested filename is a file or folder on disk, serve it up with apache as per normal
4. otherwise rewrite the requested file to prepend /htmlify/ anyway

os-loganalyze is set up as an WSGIScriptAlias at /htmlify/. This means all files that aren’t on disk are sent to os-loganalyze (or if the file is on disk but matches a file we want to mark up it is also sent to os-loganalyze). os-loganalyze then does the following:

1. Checks the requested file path is legitimate (or throws a 400 error)
2. Checks if the file is on disk
3. Checks if the file is stored in swift
4. If the file is found markup (such as anchors) are optionally added and the request is served
   1. When serving from swift the file is fetched via the swiftclient by os-loganlayze in chunks and streamed to the user on the fly. Obviously fetching from swift will have larger network consequences.
5. If no file is found, 404 is returned

If the file exists both on disk and in swift then step #2 can be skipped by passing ?source=swift as a parameter (thus only attempting to serve from swift). In our case the files exist both on disk and in swift since we want to compare the performance so this feature is necessary.

So now that we have the logs uploaded into swift and stored on disk we can get into some more interesting comparisons.

Testing performance process

My first attempt at this was simply to fetch the files from disk and then from swift and compare the results. A crude little python script did this for me: http://paste.openstack.org/show/122630/

The script fetches a copy of the log from disk and then from swift (both through os-loganalyze and therefore marked-up) and times the results. It does this in two scenarios:

1. Repeatably fetching the same file over again (to get a good average)
2. Fetching a list of recent logs from gerrit (using the gerrit api) and timing those

I then ran this in two environments.

1. On my local network the other side of the world to the logserver
2. On 5 parallel servers in the same DC as the logserver

Running on my home computer likely introduced a lot of errors due to my limited bandwidth, noisy network and large network latency. To help eliminate these errors I also tested it on 5 performance servers in the Rackspace cloud next to the log server itself. In this case I used ansible to orchestrate the test nodes thus running the benchmarks in parallel. I did this since in real world use there will often be many parallel requests at once affecting performance.

The following metrics are measured for both disk and swift:

1. request sent – time taken to send the http request from my test computer
2. response – time taken for a response from the server to arrive at the test computer
3. transfer – time taken to transfer the file
4. size – filesize of the requested file

The total time can be found by adding the first 3 metrics together.

 

Results

Home computer, sequential requests of one file

 

The complementary colours are the same metric and the darker line represents swift’s performance (over the lighter disk performance line). The vertical lines over the plots are the error bars while the fetched filesize is the column graph down the bottom. Note that the transfer and file size metrics use the right axis for scale while the rest use the left.

As you would expect the requests for both disk and swift files are more or less comparable. We see a more noticable difference on the responses though with swift being slower. This is because disk is checked first, and if the file isn’t found on disk then a connection is sent to swift to check there. Clearly this is going to be slower.

The transfer times are erratic and varied. We can’t draw much from these, so lets keep analyzing deeper.

The total time from request to transfer can be seen by adding the times together. I didn’t do this as when requesting files of different sizes (in the next scenario) there is nothing worth comparing (as the file sizes are different). Arguably we could compare them anyway as the log sizes for identical jobs are similar but I didn’t think it was interesting.

The file sizes are there for interest sake but as expected they never change in this case.

You might notice that the end of the graph is much noisier. That is because I’ve applied some rudimentary data filtering.

	request sent (ms) – disk	request sent (ms) – swift	response (ms) – disk	response (ms) – swift	transfer (ms) – disk	transfer (ms) – swift	size (KB) – disk	size (KB) – swift
Standard Deviation	54.89516183	43.71917948	56.74750291	194.7547117	849.8545127	838.9172066	7.121600095	7.311125275
Mean	283.9594368	282.5074598	373.7328851	531.8043908	5091.536092	5122.686897	1219.804598	1220.735632

 

I know it’s argued as poor practice to remove outliers using twice the standard deviation, but I did it anyway to see how it would look. I only did one pass at this even though I calculated new standard deviations.

 

	request sent (ms) – disk	request sent (ms) – swift	response (ms) – disk	response (ms) – swift	transfer (ms) – disk	transfer (ms) – swift	size (KB) – disk	size (KB) – swift
Standard Deviation	13.88664039	14.84054789	44.0860569	115.5299781	541.3912899	515.4364601	7.038111654	6.98399691
Mean	274.9291111	276.2813889	364.6289583	503.9393472	5008.439028	5013.627083	1220.013889	1220.888889

 

I then moved the outliers to the end of the results list instead of removing them completely and used the newly calculated standard deviation (ie without the outliers) as the error margin.

Then to get a better indication of what are average times I plotted the histograms of each of these metrics.

Here we can see a similar request time.
 

Here it is quite clear that swift is slower at actually responding.
 

Interestingly both disk and swift sources have a similar total transfer time. This is perhaps an indication of my network limitation in downloading the files.

 

Home computer, sequential requests of recent logs

Next from my home computer I fetched a bunch of files in sequence from recent job runs.

 

 

Again I calculated the standard deviation and average to move the outliers to the end and get smaller error margins.

	request sent (ms) – disk	request sent (ms) – swift	response (ms) – disk	response (ms) – swift	transfer (ms) – disk	transfer (ms) – swift	size (KB) – disk	size (KB) – swift
Standard Deviation	54.89516183	43.71917948	194.7547117	56.74750291	849.8545127	838.9172066	7.121600095	7.311125275
Mean	283.9594368	282.5074598	531.8043908	373.7328851	5091.536092	5122.686897	1219.804598	1220.735632
Second pass without outliers
Standard Deviation	13.88664039	14.84054789	115.5299781	44.0860569	541.3912899	515.4364601	7.038111654	6.98399691
Mean	274.9291111	276.2813889	503.9393472	364.6289583	5008.439028	5013.627083	1220.013889	1220.888889

 

What we are probably seeing here with the large number of slower requests is network congestion in my house. Since the script requests disk, swift, disk, swift, disk.. and so on this evens it out causing a latency in both sources as seen.
 

Swift is very much slower here.

 

Although comparable in transfer times. Again this is likely due to my network limitation.
 

The size histograms don’t really add much here.
 

Rackspace Cloud, parallel requests of same log

Now to reduce latency and other network effects I tested fetching the same log over again in 5 parallel streams. Granted, it may have been interesting to see a machine close to the log server do a bunch of sequential requests for the one file (with little other noise) but I didn’t do it at the time unfortunately. Also we need to keep in mind that others may be access the log server and therefore any request in both my testing and normal use is going to have competing load.
 

I collected a much larger amount of data here making it harder to visualise through all the noise and error margins etc. (Sadly I couldn’t find a way of linking to a larger google spreadsheet graph). The histograms below give a much better picture of what is going on. However out of interest I created a rolling average graph. This graph won’t mean much in reality but hopefully will show which is faster on average (disk or swift).
 

You can see now that we’re closer to the server that swift is noticeably slower. This is confirmed by the averages:

 

	request sent (ms) – disk	request sent (ms) – swift	response (ms) – disk	response (ms) – swift	transfer (ms) – disk	transfer (ms) – swift	size (KB) – disk	size (KB) – swift
Standard Deviation	32.42528982	9.749368282	245.3197219	781.8807534	1082.253253	2737.059103	0	0
Mean	4.87337544	4.05191168	39.51898688	245.0792916	1553.098063	4167.07851	1226	1232
Second pass without outliers
Standard Deviation	1.375875503	0.8390193564	28.38377158	191.4744331	878.6703183	2132.654898	0	0
Mean	3.487575109	3.418433003	7.550682037	96.65978872	1389.405618	3660.501404	1226	1232

 

Even once outliers are removed we’re still seeing a large latency from swift’s response.

The standard deviation in the requests now have gotten very small. We’ve clearly made a difference moving closer to the logserver.

 

Very nice and close.
 

Here we can see that for roughly half the requests the response time was the same for swift as for the disk. It’s the other half of the requests bringing things down.
 

The transfer for swift is consistently slower.

 

Rackspace Cloud, parallel requests of recent logs

Finally I ran just over a thousand requests in 5 parallel streams from computers near the logserver for recent logs.

 

Again the graph is too crowded to see what is happening so I took a rolling average.

 

 

	request sent (ms) – disk	request sent (ms) – swift	response (ms) – disk	response (ms) – swift	transfer (ms) – disk	transfer (ms) – swift	size (KB) – disk	size (KB) – swift
Standard Deviation	0.7227904332	0.8900549012	434.8600827	909.095546	1913.9587	2132.992773	6.341238774	7.659678352
Mean	3.515711867	3.56191383	145.5941102	189.947818	2427.776165	2875.289455	1219.940039	1221.384913
Second pass without outliers
Standard Deviation	0.4798803247	0.4966553679	109.6540634	171.1102999	1348.939342	1440.2851	6.137625464	7.565931993
Mean	3.379718381	3.405770445	70.31323922	86.16522485	2016.900047	2426.312363	1220.318912	1221.881335

 

The averages here are much more reasonable than when we continually tried to request the same file. Perhaps we’re hitting limitations with swifts serving abilities.

 

I’m not sure why we have sinc function here. A network expert may be able to tell you more. As far as I know this isn’t important to our analysis other than the fact that both disk and swift match.
 

Here we can now see swift keeping a lot closer to disk results than when we only requested the one file in parallel. Swift is still, unsurprisingly, slower overall.
 

Swift still loses out on transfers but again does a much better job of keeping up.
 

Error sources

I haven’t accounted for any of the following swift intricacies (in terms of caches etc) for:

• Fetching random objects
• Fetching the same object over and over
• Fetching in parallel multiple different objects
• Fetching the same object in parallel

I also haven’t done anything to account for things like file system caching, network profiling, noisy neighbours etc etc.

os-loganalyze tries to keep authenticated with swift, however

• This can timeout (causes delays while reconnecting, possibly accounting for some spikes?)
• This isn’t thread safe (are we hitting those edge cases?)

We could possibly explore getting longer authentication tokens or having os-loganalyze pull from an unauthenticated CDN to add the markup and then serve. I haven’t explored those here though.

os-loganalyze also handles all of the requests not just from my testing but also from anybody looking at OpenStack CI logs. In addition to this it also needs to deflate the gzip stream if required. As such there is potentially a large unknown (to me) load on the log server.

In other words, there are plenty of sources of errors. However I just wanted to get a feel for the general responsiveness compared to fetching from disk. Both sources had noise in their results so it should be expected in the real world when downloading logs that it’ll never be consistent.

Conclusions

As you would expect the request times are pretty much the same for both disk and swift (as mentioned earlier) especially when sitting next to the log server.

The response times vary but looking at the averages and the histograms these are rarely large. Even in the case where requesting the same file over and over in parallel caused responses to go slow these were only in the magnitude of 100ms.

The response time is the important one as it indicates how soon a download will start for the user. The total time to stream the contents of the whole log is seemingly less important if the user is able to start reading the file.

One thing that wasn’t tested was streaming of different file sizes. All of the files were roughly the same size (being logs of the same job). For example, what if the asset was a few gigabytes in size, would swift have any significant differences there? In general swift was slower to stream the file but only by a few hundred milliseconds for a megabyte. It’s hard to say (without further testing) if this would be noticeable on large files where there are many other factors contributing to the variance.

Whether or not these latencies are an issue is relative to how the user is using/consuming the logs. For example, if they are just looking at the logs in their web browser on occasion they probably aren’t going to notice a large difference. However if the logs are being fetched and scraped by a bot then it may see a decrease in performance.

Overall I’ll leave deciding on whether or not these latencies are acceptable as an exercise for the reader.