Jump to content


Photo

spi kernel module - cannot disable debug messages


  • Please log in to reply
1 reply to this topic

#1 jim

jim

    Advanced Member

  • Administrators
  • 3,385 posts

Posted 12 February 2015 - 09:25 PM

I'm working on my aquarium monitoring controller (using pcDuino3) and today I have incorporated the Arduino TFT 1.77' LCD module as output of the temperatures.

The display module uses the SPI pins of the controller ... and thus I use the SPI library within the c_environment. The LCD code is very basic, meaning I reset the background color and write a bunch of output (text) with different colors. All these "high level" commands are actually a huge succession of SPI messages passed by pcDuino3 to the LCD.

The trouble is that the spi module creates HUGE number of entries within /var/log/messages and /var/log/syslog for each SPI packet that is sent. I had difficulties to report this as a BUG or not, but it is not a BUG but a serious slowdown smiley.gif

All lines look similar to:

Jun  8 18:06:32 ubuntu kernel: [17308.799243] spi_sunxi_transfer 1296
Jun  8 18:06:32 ubuntu kernel: [17308.799252] spi_sunxi_transfer 1303
Jun  8 18:06:32 ubuntu kernel: [17308.799269] [spi]:  xfer setup
Jun  8 18:06:32 ubuntu kernel: [17308.799279] [spi]: Begin transfer, txbuf ef090000, rxbuf ef090000, len 1
Jun  8 18:06:32 ubuntu kernel: [17308.799332] spi_sunxi_transfer 1296
Jun  8 18:06:32 ubuntu kernel: [17308.799341] spi_sunxi_transfer 1303
Jun  8 18:06:32 ubuntu kernel: [17308.799356] [spi]:  xfer setup
Jun  8 18:06:32 ubuntu kernel: [17308.799366] [spi]: Begin transfer, txbuf ef090000, rxbuf ef090000, len 1
Jun  8 18:06:32 ubuntu kernel: [17308.799404] spi_sunxi_transfer 1296
Jun  8 18:06:32 ubuntu kernel: [17308.799412] spi_sunxi_transfer 1303
Jun  8 18:06:32 ubuntu kernel: [17308.799426] [spi]:  xfer setup
Jun  8 18:06:32 ubuntu kernel: [17308.799436] [spi]: Begin transfer, txbuf ef090000, rxbuf ef090000, len 1
Jun  8 18:06:32 ubuntu kernel: [17308.801850] spi_sunxi_work 1253
Jun  8 18:06:32 ubuntu kernel: [17308.801871] spi_sunxi_work 1158
Jun  8 18:06:32 ubuntu kernel: [17308.801879] spi_sunxi_work 1253

Each refresh of the LCD (clearning the screen + outputting 5 lines of text) creates approximately 40.000 lines into the /var/log/messages as well as in /var/log/syslog.

Where my log files were always under 40kb daily, today they get close to 200Mb (and probably I have done about 50 invocations of the script) and I was planning to execute it every 5 minutes once it is done.

I found the file spi_sunxi.c within the a20-kernel source code and the debug is hardcoded - no way to disable it!
Here's the code within

#define SUNXI_SPI_DEBUG

#ifdef SUNXI_SPI_DEBUG
#define spi_wrn(...) do {printk("[spi]: %s(L%d) ", __FILE__, __LINE__); printk(__VA_ARGS__);} while(0)
#define spi_msg(...) printk("[spi]: "__VA_ARGS__)
#else
#define spi_wrn(...)
#define spi_msg(...)
#endif

The only solution for me now is to try and figure out if rsyslogd can be configured to ignore the messages containing "[spi]" and "spi_" from the kernel ...



#2 jim

jim

    Advanced Member

  • Administrators
  • 3,385 posts

Posted 12 February 2015 - 09:25 PM

Problem fixed!

My Arduino 1.77'' TFT speed has almost doubled! From around 7.5 seconds on average it took to clear the screen and draw 10 lines of text, its now down to 4.5 seconds. Yey smiley.gif

To get to this speed, I had to edit the spi_sunxi.c file within the patch folder. It was not enough to comment out the SUNXI_SPI_DEBUG define (which decreased the number of lines outputted from about 40k down to 25k) but also all the printk lines (which seemed debug lines anyway) and now ZERO noise from the spi component. This sped up everything with 3 seconds smiley.gif

To get to all these hoops though I had to:
a) fix the rsyslog problems I have reported here: http://pcduino.com/f...hp?topic=4490.0 (logs were not properly generated)
B) once started to program the TFT and abuse the SPI, then logs started to flood. I've tried to filter them with rsyslog -> still it was not fast enough (since matching the logs to filter them used CPU and it was roughly the same thing).
c) decided that maybe rsyslog is too slow, switched the system to use syslog-ng and added the filters there too. Same problem, many SPI lines were filtered, but some still arrived truncated (which let me to believe that the SPI is writing so much debug, that the kernel debug buffer was getting filled and lines started to be truncated).

The only solution was to actually recompile the kernel and clean up the /usr/local/src/a20-kernel/patch/linux-sunxi/drivers/spi/spi_sunxi.c file (the one in the patch folder, since it will overwrite the one in the kernel folder once the patch is applied). It would be nice to have this fixed in the next image ...






0 user(s) are reading this topic

0 members, 0 guests, 0 anonymous users