I have installed a benchmark script onto a pristine low-end linode server running Ubuntu 12.04 which generates a 10Mb wav file from a small midi file. Can anyone explain why response times can be so variable? I have recently occasionally seen elapsed times vary between 2s and 14s. CPU usage when it runs is often 100%. And then later it seems to improve.

On my laptop I see consistent behaviour of about 1s and 35-40% CPU. This is a critical issue for me and I have not yet managed to get to the bottom of it with linode support. Apart from this, my experience with linode has been absolutely excellent.

Where's the script and the MIDI file, I might try it later on today.

That is extremely kind of you. Here's the script:

#!/bin/bash
#############################################
#
# benchmark a timidity transform from
# midi to wav using a standard input midi file
#
# usage: benchmarkTimidity.sh
#
#############################################
function monitor {
START=$(date +%s%N)
timidity -Ow waltz.midi -o waltz.wav
DURATION=$((($(date +%s%N) - $START)/1000000))
echo "Timidity took $DURATION ms"
}


for (( ; ; ))
do
monitor
sleep 2
done


I'm using Timidity++ (timidity-interfaces-extra 2.13.2-40build2). Where is the best place to post the sample midi file?

There are many individual Linode VMs running on a single host machine. All of these VMs compete with one another for resources, notably CPU time and disk I/O.

Each VM is guaranteed a certain amount of CPU, but when other VMs on the host are idle, you can potentially have 8 CPU cores all to yourself. Disk I/O is managed similarly; if you're the only one reading from or writing to the disk, you get the full transfer capability.

The upshot is that CPU- or disk I/O-intensive tasks can have widely varying completion times depending on how busy other Linodes on the same host are, unlike your laptop where you consistently have access to 100% of the resources.

My first step would be to profile your application to see what the hold-up is. If you run vmstat and you see large numbers in the cpu "wa" column, it's I/O bound. If instead the "us" numbers are high, it's probably the application sucking up CPU.

You may also want to see if other services are running on your Linode (even on a "pristine" install there can be some). In particular, a package updater will use a bunch of CPU and I/O when it runs.

If the problem is that your application is simply trying to use more than your guaranteed share of CPU and I/O on a host, you can upgrade to the next size Linode; there will be half as many VMs on the host.

Another thing maybe is if the application only uses one CPU, to see whether there's a command-line flag or parallelized version that can split the work among multiple CPUs.

Just realised - you should be able to get the midi file from my application

http://www.tradtunedb.org.uk:8080/music ... waltz/midi

but I just named it 'waltz.midi' for the test.

Thanks, Vance, for the information on sharing. I pretty much thought that this had to be the case. I think it must be IO bound from what I've seen so far, but I'm not really able to afford an upgrade for what is, essentially, just a 'vanity' project!

To go into more detail on the vmstat suggestion, you can run "vmstat 1" in another window before starting your benchmark, and leave it running for the duration. That will give you an idea of how things are changing over time.

Also, it might be interesting to run timidity through the 'time' command, which will print out a summary of system resource usage after the program exits: simply change the command line to "time timidity -Ow waltz.midi -o waltz.wav" and boom, more output.

It has been a long time since I've used timidity, and it was on a single-processor machine anyway, so I can't recall if it is multi-threaded. If it isn't, that will be a bit of a bottleneck if it is CPU-bound. One thing that MIGHT help is recompiling timidity for your particular CPU (try -mtune=native or -march=native, with the caveat that -march=native will include instructions that may not be available on all Linode CPUs).

If it's I/O-bound, try instantiating a small ramdisk to store the input and output files to see if that improves things. However, since timidity loads a large number of patch files from elsewhere on the filesystem, this might not be where the I/O bottleneck is. (However, the disk cache should be rocking those patch files...)

Measurements are good. Keep measuring, no matter what!

_________________

/* TODO: need to add signature to posts */

I used my own midi file which produces a wav of 34 megs, I also commented the sleep so it runs once, on my home machine it runs in about 2 seconds, on my Linode it runs in about 6 seconds, consistently.

Many thanks to all of you, so far, for all this help. It gives me things to try before losing heart. What a responsive bunch you all are!

In the name of Science, I deployed a fresh Linode 1024 unto newark630.

linode395992 (198.74.57.101)
Ubuntu 13.04 (x86_64), kernel 3.9.3-x86_64-linode33
Intel(R) Xeon(R) CPU E5-2670 0 @ 2.60GHz (x8)

Commands:

apt-get update
apt-get dist-upgrade
wget -O waltz.midi http://www.tradtunedb.org.uk:8080/musicrest/genre/scandi/tune/konstan%2Bparempi%2Bvalssi-waltz/midi
vi benchmarkTimidity.sh   # pasted in above snippet, added "time" before the timidity execution as per my last
apt-get install timidity-interfaces-extra
bash benchmarkTimidity.sh

I let it loop a few times, with the following output from the script, and then from vmstat:

root@li546-101:~# bash benchmarkTimidity.sh 
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m2.258s
user   0m1.916s
sys   0m0.075s
Timidity took 2262 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.935s
user   0m1.850s
sys   0m0.078s
Timidity took 1938 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m2.053s
user   0m1.926s
sys   0m0.080s
Timidity took 2056 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.919s
user   0m1.832s
sys   0m0.087s
Timidity took 1922 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.975s
user   0m1.888s
sys   0m0.086s
Timidity took 1977 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m2.231s
user   0m2.128s
sys   0m0.096s
Timidity took 2234 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m2.053s
user   0m1.963s
sys   0m0.079s
Timidity took 2056 ms
^C

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  0      0 275220  31856 582180    0    0     0    36   28   43  0  0 100  0
 1  0      0 266408  31872 584920    0    0     8     0  590  116  5  0 94  1
 1  0      0 257076  31884 593800    0    0     0     0 1017   19 12  0 87  0
 0  0      0 257804  31892 599064    0    0     0     0  717   79  7  0 93  0
 0  0      0 257796  31892 599064    0    0     0     0   25   17  0  0 100  0
 1  0      0 266352  31896 584948    0    0     0     0  959  100  5  0 95  0
 1  0      0 257548  31908 594264    0    0     0    56 1377   25 12  0 87  0
 0  0      0 258392  31916 599064    0    0     0 16884  738   87  6  0 94  0
 0  0      0 258392  31916 599064    0    0     0     0   14   11  0  0 100  0
 1  0      0 266080  31920 585536    0    0     0     0 1094   94  6  0 94  0
 1  0      0 256788  31932 594512    0    0     0     0 2034   32 12  0 87  0
 0  0      0 258396  31944 598936    0    0     4 16932 1273  133  6  0 93  0
 0  0      0 258396  31944 598936    0    0     0     0   24   23  0  0 100  0
 1  0      0 266288  31948 585144    0    0     0     0  939   92  5  0 95  0
 1  0      0 256508  31964 594592    0    0     0     0 2025   19 12  0 88  0
 0  0      0 258352  31968 599064    0    0     0 16884 1299  117  6  1 94  0
 0  0      0 258392  31968 599064    0    0     0    56   32   34  0  0 100  0
 1  0      0 265832  31972 585784    0    0     0     0 1095   94  6  1 94  0
 1  0      0 256656  31988 594820    0    0     0     0 2017   16 12  0 87  0
 0  0      0 258236  31992 599064    0    0     0 16884 1224  109  6  0 94  0
 0  0      0 258236  31992 599064    0    0     0    88   32   25  0  0 100  0
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  0      0 266412  31996 585144    0    0     0     0 1114  105  6  0 94  0
 1  0      0 258616  32008 592824    0    0     0    40 2019   24 12  1 87  0
 0  0      0 258456  32016 599076    0    0     0 16884 1653  119  9  0 91  0
 0  0      0 258456  32016 599076    0    0     0     0   16   18  0  0 100  0
 1  0      0 268024  32020 583576    0    0     0     0  656  103  3  0 97  0
 1  0      0 258864  32032 592316    0    0     0     0 2016   13 12  0 87  0
 0  0      0 258380  32040 599020    0    0     0 16936 1746  135  9  1 90  0
 0  0      0 258272  32040 599020    0    0     0     0   19   15  0  0 100  0
 0  0      0 258268  32040 599064    0    0     0     0   84   58  0  0 100  0
 0  0      0 258268  32040 599064    0    0     0     0   18   13  0  0 100  0
 0  0      0 258268  32040 599064    0    0     0     0   18   19  0  0 100  0
^C

Here's what I think about it:

1) It is consistently using about 1.9 seconds of CPU time to do its bidding. It's doing so on exactly one CPU, which is why the cpu.us (user CPU percentage) column in vmstat is not going above 12% or so.
2) It is also writing out a buttload of data immediately after it is done using a lot of CPU.

So let's see what I can do about #2...

mount -t tmpfs -o size=128M tmpfs /mnt
vi benchmarkTimidity.sh   # change the output file to /mnt/waltz.wav
bash benchmarkTimidity.sh

Re-running it, I'm still around 1950 ms or so, but there's no huge I/O blorp and the variance has decreased a bit. I suspect your variance would decrease as well.

_________________

/* TODO: need to add signature to posts */

Because it's still raining outside, and I haven't done something like this in awhile:

apt-get install build-essential fakeroot dpkg-dev
apt-get build-dep timidity
apt-get source timidity
cd timidity-2.13.2
dpkg-buildpackage -rfakeroot -b
# wait
cd ..
dpkg -i *.deb   # note to self: don't bother with timidity-el
bash benchmarkTimidity.sh

OK, it is now maybe 50-100 ms slower than it was before.

cd timidity-2.13.2
vi debian/rules   # add -mtune=native to the EXTRAFLAGS
dpkg-buildpackage -rfakeroot -b
# wait
# install, etc, as above...

OK, maybe a handful of milliseconds faster, definitely not mind-blowing...

I then tried -march=native, on the off chance that my CPU has magic powers. This, believe it or not, got me about 50 ms faster, maybe down to 1900 ms or so. Worth it? No.

This did satisfy a bit of natural curiosity I had, at least

_________________

/* TODO: need to add signature to posts */

You're officially a total geek.

As a joke, I tried "-march=corei7 -funroll-loops". It did actually shave another 300 ms off of each run. This is the first time this has ever happened.

root@li546-101:~# bash benchmarkTimidity.sh 
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.653s
user   0m1.599s
sys   0m0.053s
Timidity took 1656 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.573s
user   0m1.527s
sys   0m0.045s
Timidity took 1576 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.570s
user   0m1.532s
sys   0m0.038s
Timidity took 1574 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.529s
user   0m1.474s
sys   0m0.055s
Timidity took 1531 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.574s
user   0m1.533s
sys   0m0.040s
Timidity took 1577 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.679s
user   0m1.621s
sys   0m0.057s
Timidity took 1683 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.522s
user   0m1.475s
sys   0m0.046s
Timidity took 1525 ms
Playing waltz.midi
MIDI file: waltz.midi
Format: 0  Tracks: 1  Divisions: 480
Sequence: Konstan parempi valssi
Playing time: ~99 seconds
Notes cut: 0
Notes lost totally: 0

real   0m1.562s
user   0m1.515s
sys   0m0.047s
Timidity took 1565 ms

_________________

/* TODO: need to add signature to posts */

I'm staggered - what wonderful help. hoopycat - it's very useful to know it's CPU bound followed by being IO bound. Your original figures are pretty much what I was seeing before it suddenly (and temporarily) deteriorated 5 or 6 days ago. I'm amazed you can shave some time off.

I'm beginning to think, though, that I'm being too ambitious anyway attempting to do all the rendering server-side. I've just discovered http://mudcu.be/midi-js/ exists, so I think I'll also take a look at possibly changing the application to do the rendering client-side.

Thanks again for all your help - most impressive.

Yeah, I probably wouldn't bother recompiling for that improvement (for various reasons), but a tmpfs ramdisk might actually help out quite a bit (especially if you aren't keeping the .wavs around).

Have fun!

_________________

/* TODO: need to add signature to posts */