Improve Volume Wheel Daemon (Bounty!)

[netcat]

We have ruled all this things out already. The shown high usage is ONLY caused by the read. Which you can simply check by deleting the setting line from the code and end up with no cpu difference.

Ok, so figure out why iio_channel_attr_read_double() is taking so long, see if it does unneccesary things or if there is a different approach.

Btw - if you comment out the read the conditional will always fail and the write will never happen either. Just checking that you considered this.

I think this is a very easy problem at this point. It's a simple process that you can debug. You can solve it immediately or prove its a hardware issue with judicious printf's.

 

[elw3]

*sigh* You got this wrong. Again.
Okey lets do some comprehensive analysing:
Let the code be a simple read loop:

local File,_=io.open("FILE", "r")
File:setvbuf("no")
Readfile= function() File:seek('set') return File:read() end
for x=1,10000 do
 Readfile()
end

And lets call it with _time_ four times with different entries for FILE.
First our volume wheel at /sys/bus/iio/devices/iio:device4/in_voltage2_input
Next /proc/stat which stands as reference for a kernel created info file.
Next something from ram at /dev/shm/bla to see how fast reading itself is.
Last we comment out the read line to see how fast the loop itself is.
The results are:

elw@elw-pyra:~/mm/vol$ time ./lua bla.lua
real    0m31,004s
user    0m0,107s
sys    0m3,393s
elw@elw-pyra:~/mm/vol$ time ./lua bla.lua
real    0m0,975s
user    0m0,265s
sys    0m0,691s
elw@elw-pyra:~/mm/vol$ time ./lua bla.lua
real    0m0,167s
user    0m0,067s
sys    0m0,094s
elw@elw-pyra:~/mm/vol$ time ./lua bla.lua
real    0m0,012s
user    0m0,001s
sys    0m0,012s

Note how our volume wheel takes a whooping 30s to finish. The system however worked 3s in cpu time, to add up the total time we can deduce that the chip took 27s to answer 10000 requests.
If we want to benchmark the wheel daemon we need to ensure the tool that measures only accounts for cpu time since a blocked read is not identical to a sleep counting wise, this is not granted, but should be the case with the common tools like top.
The proc file being a lot faster, we take the _real_ time since we can be sure there is no chip to wait for. We learn that the code that generates our volume file takes around 3 times longer than the code that generates the cpu information. This is is bad, /proc/stat is a large file with a lot of info in it. And its generation is still faster than the single number for our wheel.
From the last two tries we can only see that read() is what takes the actual time in this loop but also that the entire loop overhead is negligible compared to what accessing/generating the device file costs.
Now for the very best part:

elw@elw-pyra:~/mm/vol$ time ./lua bla.lua
real    2m1,305s
user    0m0,051s
sys    1m30,014s

This is the result of turning the volume wheel to 0.
Thats over 1 minute cpu time used to generate a little number. This is not caused by the chip, we can clearly see the chip being as fast as before.
This is caused by kernel code that generates the file. This is a proof of it having a bug.

Luckily in_voltage2_raw does not seem to suffer from this. And no i tested this file too and except when the value is 0 there is no speed difference.
I had reasons to use input instead raw before, it shaved of a few lines of code, but with this catastrophic result it must be avoided.

 

[Djoga'Ro]

I'm just wildly speculating here. Could it be that there are more that one queue for different kinds of access requests to that file, which then still get interlaced, and that the kernel code to update that file keeps the queue for blocking writes filled up so that the unblocking read gets delayed everytime until a number of earlier write requests got processed?

 

[elw3]

*scratches head*
Can you rephrase that so that i can understand it?
You think more than one process accesses this file?

 

[Djoga'Ro]

I have no idea, what or how things are happening in the kernel - that's why I called myself out preenptively for being wildly speculative.
Maybe the code that reads the "sensor", doesn't write synchronously, but dispatches the write job, weither as thread, task, job description or something else. ? As I said, I'm just guessing. It's just that I can't think of anythings else but blocking writes. And lots of them, since a single write of such a short value should be fast. ?

Or there's a sleep in that sensor reading code, but at the wrong place, like while blocking.

 

[levi]

Note how our volume wheel takes a whooping 30s to finish. The system however worked 3s in cpu time, to add up the total time we can deduce that the chip took 27s to answer 10000 requests.

That doesn't sound too bad to me. It means it completes one read in 2.7ms. I mean that's a lot slower than reading an actual real file on the filesystem, which I measure on this system to be a matter of about 15μs, but still not excessive if you're only doing it once every half second or so.

 

[elw3]

This hopefully may work:
It Implements auto shutdown when no sound is played, i do not know how reliable this works yet tho.
Further it takes settings as arguments.
"Speed" is the polling delay in μs, default is 100000 which is 0.1s.
"Range" is the expected max wheel value, default is 2000 which causes it to go up to 102%. Lower values may break your ears, higher ones will lower the max volume.
"volume Speed 2000000 Range 4000" Will give you 2s polling time and and a 50% max volume.

There is no pulse integration but instead a very ugly system call. This has pros and cons, mainly turning the wheel uses more resources while its using less resources all other times.
I tried to include it but coding wise pulse is a monster to integrate, even if you manage to do it, no one would be willing to maintain it, let alone solving all the compiling problems.
So i stop here saying this is no smart move.

Benchmark: Obviously while nothing is playing the usage is zero.
But in usage there is no noteworthy difference to the already existing pyra_volume.c file.
This quick test shows slight tendency towards my tool:
real 1m1,233s
user 0m0,025s
sys 0m0,423s
vs pyra_volumed:
real 1m3,811s
user 0m0,100s
sys 0m0,582s
But ive seen other results too, so one needs to run it way longer to actually see a difference, in theory they should be identical.

Test this and report any misbehaving.

Also, its not written in lua this time, i shaved that cause i thought i needed it for pulse, ohwell, jokes on you, a lua version would be one if case shorter.

EDIT: I have not accounted that paths change on reboot. This tool will maybe just do nothing at all when invokened since it monitors the wrong file
Ill fix this tomorrow. Blah, its always the tiny little details...

 

[EvilDragon]

Cool Sounds like we're getting close to a bounty here
Next step would be to find out why the reading takes so much CPU time - but that doesn't have to do anything with the bounty

 

[levi]

Wikipedia already has fairly comprehensive documentation, if you know where to look:

Analog-to-digital converter - Wikipedia

en.wikipedia.org

Basically we can't use the fastest type of ADC here because they suffer from drift, and the other types all take some time to get a decent reading.

 

[EvilDragon]

But would that increase the CPU usage? If it's just waiting for a value, it shouldn't keep the CPU busy, should it?

 

[Letalis Sonus]

Basically we can't use the fastest type of ADC here because they suffer from drift, and the other types all take some time to get a decent reading.

Don't forget the jitter, even on a constant voltage there will always be some kind of overlaying error signal. You either have to discard several bits if the lower precision is sufficient for you, or you have to filter the measurements, e.g. by taking multiple measurements and calculating their average.

But would that increase the CPU usage? If it's just waiting for a value, it shouldn't keep the CPU busy, should it?

That depends on how the waiting bit is implemented, busy waiting is fairly common if the programmer expects only small delays because the alternative would be yielding the rest of the current time slot of the application, which will cause a rather large delay due to scheduling and several context switches.

I'd expect blocking functions like read() to be of the busy waiting kind (in this case it might be the kernel code doing the waiting, though). If you know that you're waiting slightly longer it is a better idea to use non-blocking functions like recv() and explicitly yield() if no new data is available, but I'm not sure how device files behave in this case.

 

[elw3]

Next step would be to find out why the reading takes so much CPU time

See above, but TLDR: The code that generates the /dev/io file is faulty.
It also gives different cpu usage on different wheel positions which hints on a conversion problem.
Inspecting this code may be a bigger task tho.

My bigger concern is: Dont we have more sensors like that? Has the battery voltage reader the same problem?

But would that increase the CPU usage? If it's just waiting for a value, it shouldn't keep the CPU busy, should it?

How do you measure?
Are we sure of it being busy in the first place? Measuring CPU usage isnt exactly accurate. I can imagine kernel IO stuff messes quite a lot with measuring methods.
I mean its exactly as one observes: It shows something that should not be not there. Is it really there or are we fooled by the numbers?
I tend to trust _time_, but i am not convinced.
One needs to dig into /proc/ if he wants to find answers.


Common give some feedback.
Any ideas for additional arguments?
Is the position>wheel scaling alright?
The scaling currently looks like (Value+(MAX/100)-1)/(MAX/100)>volume%.
I found Value^0.61 to give a better scaling but this math is quite demanding. Thoughts?

 

[Letalis Sonus]

It also gives different cpu usage on different wheel positions which hints on a conversion problem.

...or simply shows that the ADC measurement does not have a fixed runtime. Look at the different types of ADCs in the Wikipedia article, depending on how the ADC is implemented the input voltage can have a direct influence on the time it takes to complete the measurement. ADCs work by approximation, approximation takes time.

 

[elw3]

That doesnt match the numbers i got above.

 

[netcat]

I found Value^0.61 to give a better scaling but this math is quite demanding. Thoughts?

It should be logarithmic not exponential. Aka audio taper.

 

[ouzle]

I'm trying to find time to test this @elw3, hopefully on the train home this evening.

I'd also like to understand why the TI PALMAS driver (<= link to driver) uses alot of CPU to update "/sys/bus/iio/devices/iio:device3/in_voltage2_*"

The TI PALMAS driver reads the voltages from the TWL6037 power controller chip. The TWL6037 chip is on the OMAP5432 board. TI don't provide a datasheet for the TWL6037 unless you ask TI sales.

The driver asks for a reading from the ADC and uses an interrupt to get the result. So why should the CPU be busy?

 

[EvilDragon]

I'd also like to understand why the TI PALMAS driver (<= link to driver) uses alot of CPU to update "/sys/bus/iio/devices/iio:device3/in_voltage2_*"

The TI PALMAS driver reads the voltages from the TWL6037 power controller chip. The TWL6037 chip is on the OMAP5432 board. TI don't provide a datasheet for the TWL6037 unless you ask TI sales.

I've got the datasheets, so we can check that up.

But yeah, a lot of TWL stuff seems to be a bit weird. Sometimes, USB doesn't work at all. Even connecting a mouse it says that the mouse uses too much power. I think that's also why the modem sometimes doesn't appear.
It can't be too weak power lines in hardware - as after a restart, you can even easily connect a harddisk to USB and it works without any issues.

I also have some CPU boards where vibration only sometimes work - which sounds like the motor doesn't get enough power. So the whole power setup of the Palmas / TWL seems to be a bit borked.

 

[elw3]

I am going to ad the argument "Timeout" which defines when the polling should be reduced or shut down after a stream started.
So when you start watching a movie you have like 20 seconds to adjust the volume on fast poll and then it polls every second or so.
Question is: Should touching the wheel after that time starts a new round of fast poll? I dont want to overload the loop with checks.

Todo: Ad two step jitter check, the second applied to percentage which should shave of a bit cpu usage and a few volume changes.
Add a check to see if thread already runs, currently when you stop/start playing within 0.1s it can lead to double cpu usage.

If you have more suggestions, now is a good time to mention them.
In particular id like to add a suspend feature for when a program wants to misuse the wheel for something else and the rare case you want to play music while misusing it.
Eg for a game, the approach would be that i add the file /dev/shm/lock to the watchlist and the program would need to create it, open it and close it again and thus disable polling.
But something tells me that no one ever would want to make use of that and its just a waste of bytes to add it.

 

[ouzle]

If you have more suggestions, now is a good time to mention them.
In particular id like to add a suspend feature for when a program wants to misuse the wheel for something else and the rare case you want to play music while misusing it.
Eg for a game, the approach would be that i add the file /dev/shm/lock to the watchlist and the program would need to create it, open it and close it again and thus disable polling.
But something tells me that no one ever would want to make use of that and its just a waste of bytes to add it.

OK, I've given it a spin now.

Testing the original pyra_thermald control

• Ran "alsamixer" with no sound playing
  • The potentiometer has no effect on the PulseAudio output level.
  • Pressing "<F6> Select sound card" => "Letux Cortex 15" I now see the "Handsfree" ALSA channel moving with the potentiometer
• Started playing a track in my favourite media player (qmmp).
  • I get the full volume range from silent to blasting
  • Fast response.
• Ran "PulseAudio Volume Control" with track still playing. No movement seen on the controls.

Testing elw3's volume daemon

• Stopped pyra_volumed and started volume
  

  sudo service pyra_volumed stop
  ./volume

• Ran "alsamixer" with no sound playing.
  • As expected, nothing moves because the new script sleeps until a sound plays.
• Opened up another terminal and hit <left> to get the "blip" notification. Tabbed back to alsamixer.
  • As expected, the PulseAudio volume mixer now moves with the potentiometer for several seconds after the sound.
  • Then the pot disconnects when the script goes back to sleep.
  • I see the same behaviour from the "PulseAudio Volume Control" app
• Started playing a track in QMMP
  • Only get half the volume range - silent to half volume
  • So... opened alsamixer and <F6> => "Letux Cortex 15". I see that the ALSA handsfree channel is still set to 30%
  • Turned up the ALSA volume to full => now the pot gives the full volume range,
  • Fast, and responsive

Maybe call snd_mixer_selem_set_playback_volume_all(elem, volume); at the start of your code to set the ALSA volume to full?

 

[levi]

I personally think polling every half second while music is playing would be enough. I wouldn't mind if it slept while the system wasn't playing any sound, provided it checked you hadn't turned the volume completely off before playing a system notification sound.