Kernel log messages from smart reflex AM335x

Peter T-Innova

Intellectual 640 points

Other Parts Discussed in Thread: AM3352

Hi.

A custom board (mimicing the starter kit to some content) with AM3352 runs linux kernel 3.2.0.

Two board are tested, both equipped with PoE. Both boards are running fine and the cpu load is low.

On one board there are some initial messages at boot time like:

[ 4.865671] SR 0: curr=1137500, delta_v=-56875, calc=1080625, act=1087500, gain=00

[ 4.902940] SR 1: curr=1262500, delta_v=-63125, calc=1199375, act=1200000, gain=00

[ 6.111371] SR 0: curr=1087500, delta_v=-91641, calc=995859, act=1000000, gain=1b

[ 6.114179] SR 1: curr=1200000, delta_v=-78120, calc=1121880, act=1125000, gain=27

At the other board, the kernel log is spammed by these messages, like:

[73092.291143] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73093.551144] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73094.811151] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73096.071147] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73097.331140] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73098.591128] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73099.851138] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73101.111135] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73102.371135] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73103.631130] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73104.891128] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73106.151140] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73107.411140] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73108.671133] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73109.931200] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73111.191184] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73112.451163] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73113.711150] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73114.971135] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[73116.231139] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

and sometimes something like:

[72557.821149] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72559.081156] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72560.341125] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72561.601471] SR 1: curr=1112500, delta_v=-15249, calc=1097251, act=1100000, gain=27

[72808.311279] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

[72914.632521] SR 1: curr=1100000, delta_v=3783, calc=1103783, act=1112500, gain=27

[72915.891557] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72917.151163] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72918.411152] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72919.671145] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72920.931140] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

[72922.191150] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Jun 16 08:18:14 wped kernel: [ 386.431227] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Jun 16 08:18:15 wped kernel: [ 387.691237] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Jun 16 08:18:16 wped kernel: [ 388.951226] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Jun 16 08:18:17 wped kernel: [ 390.211569] SR 1: curr=1112500, delta_v=-15249, calc=1097251, act=1100000, gain=27

Jun 16 08:29:03 wped kernel: [ 1035.691407] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:33:49 wped kernel: [ 1322.031308] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:38:49 wped kernel: [ 1622.261432] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:39:02 wped kernel: [ 1635.061303] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:43:31 wped kernel: [ 1903.821317] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:47:21 wped kernel: [ 2133.961394] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:52:17 wped kernel: [ 2429.401331] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 08:56:33 wped kernel: [ 2685.451388] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 09:01:28 wped kernel: [ 2980.961322] SR 1: curr=1100000, delta_v=0, calc=1100000, act=1100000, gain=27

Jun 16 09:02:55 wped kernel: [ 3067.931691] SR 1: curr=1100000, delta_v=3783, calc=1103783, act=1112500, gain=27

Jun 16 09:02:56 wped kernel: [ 3069.191643] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Jun 16 09:02:58 wped kernel: [ 3070.451301] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Jun 16 09:02:59 wped kernel: [ 3071.711262] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Both board should be the same. Though they are not fed by the exact same power source (router) via PoE.

My question is; why is one of the boards spamming the kernel log with all these SR (smart reflex) messages? What could be the difference between the boards?

What action could be done?

Tnx / Br

over 10 years ago

0 Biser Gatchev-XID over 10 years ago

TI__Guru**** 393215 points

These are just messages from power management. Nothing harmful. I will ask the SW team if these can be suppressed.

0 Peter T-Innova over 10 years ago in reply to Biser Gatchev-XID

Intellectual 640 points

Thanks Biser.

It should be good if the messages could be suppressed.

But also, why are they emitted?

Why is there such a difference between the two boards running identical software?

Both powered via PoE, but not from the same source/type of PoE capable router.

0 Biser Gatchev-XID over 10 years ago in reply to Peter T-Innova

TI__Guru**** 393215 points

These are very minimal and complex adjustments. The reason can be simply the difference between the processors themselves (e.g. coming from different batches). The SR always tries to run the processor at the minimum possible voltage, and this usually differs from chip to chip.

0 Yordan Kovachev over 10 years ago in reply to Peter T-Innova

TI__Guru**** 161600 points

Hi,

As I see from kernel 3.2 sources these messages come from arch/arm/mach-omap2/am33xx-smartreflex-class2.c driver. Specifically from the set_voltage() function:
printk(KERN_DEBUG "SR %d: curr=%d, delta_v=%d, calc=%d, act=%d, gain=%02x\n",
i, prev_volt, delta_v, new_volt,
regulator_get_voltage(sr->sen[i].reg),
sr->sen[i].opp_data[sr->sen[i].curr_opp].e2v_gain);
You can:
- comment this specific kernel print
- disable debug prints --- NOT recommended
- change the printk() to pr_info and run your kenrel with lower loglevel

Best Regards,
Yordan

0 Peter T-Innova over 10 years ago in reply to Biser Gatchev-XID

Intellectual 640 points

Hi Biser.

Have You got any response from the sw team?

Perhaps I should need to suppress them. But even better would be to know why they are being output. There seems to be no real (changing) information in the rows being output every second.

[ 74.886154] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27
[ 76.162298] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27
[ 77.416204] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27
[ 78.676165] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27
[ 79.936142] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Now I have verified this behaviour on one more pcb. So some pcb's give SR-messages almost every second, and others don't. All boards powered one at a time from same source (RJ45 PoE) and running same software.

CPU and PMIC labeled the same on all boards;

CPU:
AM3352ZCZD72
2AASHQW G1
962 ZCZ

PMIC:
T65910
A3A1
TI 26K
D76S G4

So the questions which still remain are:

1. Why are some boards giving SR-messages almost every second and some are not.

2. What is the real usage/information in the same row almost every second? No value is changed. Why is it displaying the same information all the time? Any action that needs to be taken?

3. If one can not find the hw cause for these frequent rows (which of course would be the best solution), is it perfectly safe to disable them?

4. How to disable them? I can modify and recompile the kernel, but there may be some other sw/OS way?

(I don't really like disabling too much of debug/warning messages. I would rather see that they contain something meaningful when they are given by the program.)

Br Peter

0 Peter T-Innova over 10 years ago in reply to Yordan Kovachev

Intellectual 640 points

Thanks.

I don't really like to comment out the messages when I don't know why they are given.

They don't give much information; same data given in a row almost every second.

Br Peter

0 Peter T-Innova over 10 years ago in reply to Peter T-Innova

Intellectual 640 points

Hi.

I don't know if there perhaps is some vacation going on. But I really should appreciate some comments on my questions regarding the SR debug messages (1-4).

These kind of not very informative (?) rows are keep filling up the file system log directory:

....

Aug 24 08:15:05 wped kernel: [383545.095730] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:06 wped kernel: [383546.355715] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:08 wped kernel: [383547.615716] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:09 wped kernel: [383548.875710] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:10 wped kernel: [383550.135704] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:11 wped kernel: [383551.395720] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:13 wped kernel: [383552.655700] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:14 wped kernel: [383553.915709] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:15 wped kernel: [383555.175698] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:17 wped kernel: [383556.435713] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:18 wped kernel: [383557.695719] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:19 wped kernel: [383558.955703] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:20 wped kernel: [383560.215715] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:22 wped kernel: [383561.475719] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

Aug 24 08:15:23 wped kernel: [383562.735693] SR 1: curr=1112500, delta_v=-11427, calc=1101073, act=1112500, gain=27

....

Thanks / Br Peter

0 Biser Gatchev-XID over 10 years ago in reply to Peter T-Innova

TI__Guru**** 393215 points

I have asked the SW team to revisit this thread.

0 Yordan Kovachev over 10 years ago in reply to Biser Gatchev-XID

TI__Guru**** 161600 points

Hi Peter,

As I said these come from static void set_voltage() function.
And they show the calculations done in SR.
curr= returns the value of the regulator output voltage -> regulator_get_voltage() function in drivers/regulator/core.c (current voltage outputted from the corresponding regulator).
delta_v= returns the value written in SR error register
calc= returns curr - delta_v
act= returns the actual voltage set in the regulator -> again regulator_get_voltage() is used to obtain this value.

The KERN_DEBUG parameter passed to the printk() in set_voltage() should prevent this message from appearing, unless you enable the verbose output or use higher loglevel in the kernel. I was able to get persistent messages like yours on my BBB:
[ 76.706756] SR 1: curr=1300000, delta_v=-9800, calc=1290200, act=1300000, gain=32
when I removed KERN_DEBUG from the printk().

The message is outputted multiple times, because it is located in a for (i = 0; i < sr->no_of_sens; i++), and the set_voltage() function is called for each module that requires a voltage change from the corresponding regulator.

Can you please share the content of your set_voltage() function (have you done any modifications)?
Can you provide under what conditions these messages occur? Are you just booting the board and let it generate the log? or are you using (enabling/disabling) different IPs and you see these messages?

In general these are not error messages, but show you the calculations done by the SR for different regulators.

Best Regards,
Yordan

0 Peter T-Innova over 10 years ago in reply to Yordan Kovachev

Intellectual 640 points

Hi Yordan. Thanks for answer.

Well this is a late reply, but the problem still exists.

You wrote "The message is outputted multiple times, because...".

This is not the case for me. I believe I pasted the output from my kernel logs before, I'll do it again here below.
One can then see that kernel outputs same levels, same data, for the same SR number, number 1. That is, the loop is just doing on turn.

The multiple messages, for the same levels, and the same data (no new info. in the rows), comes from that the the set_voltage function is called several times. So something is wrong, or strange.

Oct 16 06:40:28 kernel: [58741.336867] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:30 kernel: [58742.596857] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:31 kernel: [58743.856829] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:32 kernel: [58745.116873] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:33 kernel: [58746.376850] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:35 kernel: [58747.636852] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:36 kernel: [58748.896864] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24
Oct 16 06:40:37 kernel: [58750.156838] SR 1: curr=1112500, delta_v=-10548, calc=1101952, act=1112500, gain=24

Same not necessary data on every line, like every second.

I should say the messages occur during normal conditions. Maybe there is something not normal with the board, but there are no special conditions. And again, these messages occur on some boards, not all of them.

I have to find out why the set_voltage is called repeatable.

If it does not seem to be any problem with this, I could perhaps turn the log message of in set_voltage.
Or, adjust the code so that ot only prints out of the message if any value has _changed_ (that should be better logic).

I paste source of set_voltage below.

Thanks, Br Peter

set_voltage:

static void set_voltage(struct work_struct *work)
{
struct am33xx_sr *sr;
int prev_volt, new_volt, i, ret;
s32 delta_v;

sr = container_of((void *)work, struct am33xx_sr, work);

for (i = 0; i < sr->no_of_sens; i++) {
if (sr->sen[i].irq_status != 1)
continue;

/* Get the current voltage from PMIC */
prev_volt = regulator_get_voltage(sr->sen[i].reg);

if (prev_volt < 0) {
dev_err(&sr->pdev->dev,
"%s: SR %d: regulator_get_voltage error %d\n",
__func__, i, prev_volt);

goto reenable;
}

delta_v = get_errvolt(sr, i, prev_volt, 0);
new_volt = prev_volt + delta_v;

if (delta_v != 0) {
ret = regulator_set_voltage(sr->sen[i].reg, new_volt,
new_volt + sr->uvoltage_step_size);

if (ret < 0)
dev_err(&sr->pdev->dev,
"%s: regulator_set_voltage failed! (err %d)\n",
__func__, ret);
}

/* this is the primary output for debugging SR activity */
printk(KERN_DEBUG "SR %d: curr=%d, delta_v=%d, calc=%d, act=%d, gain=%02x\n",
i, prev_volt, delta_v, new_volt,
regulator_get_voltage(sr->sen[i].reg),
sr->sen[i].opp_data[sr->sen[i].curr_opp].e2v_gain);

reenable:
/* allow time for voltage to settle before re-enabling SR
module and interrupt */
schedule_delayed_work(&sr->sen[i].work_reenable,
msecs_to_jiffies(sr->irq_delay));
}
}

0 Peter T-Innova over 10 years ago in reply to Peter T-Innova

Intellectual 640 points

I just came to think about it; what if the "SR code" tries to modify some voltage level (for some reason), but can't? Then perhaps it will call the set_voltage function repeatable, because it can't get the task done.
Do my log messages imply that the voltage level has hit some upper or lower level?

0 Yordan Kovachev over 10 years ago in reply to Peter T-Innova

TI__Guru**** 161600 points

Hi Peter,

Sorry for the late response.

I am looking into this.

In the mean time, is it possible to transition one of the boards to a newer SDK (i.e. SDK.02.00.01.07, kernel v4.1)? There have been quite a lot of updates in linux kernel sice v3.2

Best Regards,
Yordan

0 Peter T-Innova over 10 years ago in reply to Yordan Kovachev

Intellectual 640 points

Hi Yordan.

Thanks for reply. Yes, it is a very good idea to upgrade the kernel. Though this should imply some amount work and there is short of time right now.

As for now, it seems like the SR set_voltage function tries to set some voltage, but the action does not go through all the way. Making it come back and try again and again... resulting in all these very much not necessary rows. It should be good to get a confirmation that this really is the case. Then, if it is the case, comes next question, what prevents the voltage adjustment?

Br Peter

Processors

Processors forum

Kernel log messages from smart reflex AM335x