Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging: rtt: Fix data_out_block_mode() return value #24647

Closed

Conversation

XavierChapron
Copy link
Contributor

Should fix #21514

@zephyrbot
Copy link
Collaborator

zephyrbot commented Apr 23, 2020

All checks are passing now.

Tip: The bot edits this comment instead of posting a new one, so you can check the comment's history to see earlier messages.

@koffes
Copy link
Collaborator

koffes commented Apr 23, 2020

I have performed a test and I can no longer see the issue described in #21514. If this PR or some other PR resolved it is unknown.

@XavierChapron
Copy link
Contributor Author

@koffes Just to be sure that we are talking about the same issue, in #21514 you said:

Currently using the logger with mostly default settings on the nRF53.
Whilst using LOG_WRN in a high frequency loop, I would expect to see something like:
--- 71 messages dropped ---
This usually happens. Though, sometimes the logger skips a series of prints without the "messages dropped" warning.

Without this commit, I'm having the same behavior: many messages dropped without the --- xx messages dropped --- warning.
With this commit, I still have messages dropped but the warning is correctly displayed.

@koffes
Copy link
Collaborator

koffes commented Apr 24, 2020

@XavierChapron We are in agreement :) I also have messages dropped, but then the warning is correctly displayed.

@XavierChapron
Copy link
Contributor Author

@nordic-krch @nashif @jhedberg Can you have a look please?

@@ -222,7 +222,7 @@ static int data_out_block_mode(u8_t *data, size_t length, void *ctx)
}
} while ((ret == 0) && host_present);

return ((ret == 0) && host_present) ? 0 : length;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i am not convinced that this is good solution. host presence information is not taken into account. That means that if host is not connected RTT backend will never drop the message. That will result in logger working in overflow mode all the time: adding new log entry will require freeing other message and that degrades performance of the logger. I will dig deeper into it to see if something else can be done.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@nordic-krch Just to be sure, do we agree than in the current implementation the while is exited with either :

  • Data copied ret == 1 which lead to returning length
  • host not present, which lead to returning length

Therefore the current implementation can be changed to: return length; and this is wrong.

Concerning the behavior in cases where the host is not connected, I'm not familiar enough with the log API and the overflow mode.
However is there really a performance change here?

  • If host is connected, message need to be allocate then immediately freed.
  • if host is not connected and we keep current behavior, messages are allocated then immediately freed.
  • if host is not connected and we change the behavior, messages are allocated then freed later when we need to store new logs.

If I don't miss something, log are always allocate an freed only once in each scenario.

Anyway, in my opinion, if something needs to be done concerning log performance when the host is not present, it should be done in the upper level, not in rtt particular implementation using a "hack" of the log API (always returning length even when logs where dropped).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Therefore the current implementation can be changed to: return length;

yes.

and this is wrong.

no. When log messages are processed for each backend then strings are flushed chunk by chunk using function provided by the backend (data_out_block_mode in rtt case). It is expected that even if it fails to send whole data using one call, it will succeed eventually:

processed = outf(buf, len, ctx);

If RTT is not connected and it would return 0 data processed then log processing would actually stuck. So RTT must support case to consume the data if host is not reading it.

I'm not sure yet what is the issue you see. If you have host connected then host_present should always be set to true. The problem may be caused by setting falsely setting host_present to false. Can you describe the scenario and log configuration when you see this issue? Is immediate mode on or not?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My scenario is quite similar to #21514 one.

My host is connected but I try to output too many messages too fast. Therefore messages have to be drop and they are.
But currently the user is not (always?) notified that messages have been dropped with the --- xx messages dropped --- warning.
With the patch proposed in this PR, some messages are still dropped, but user is always notified.

But with your explanation I can see that this patch doesn't handle properly situations where the host is not present at all (and not just too busy).
However, I still think that this should be handle in log_core level, probably with log_backend_is_active() implementation.

Copy link
Contributor Author

@XavierChapron XavierChapron May 18, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@nordic-krch As you mentioned, this patch is not correct when host is not present for a long time as buffer_write() implementation in log_output.c will create an infinite loop.

But I don't see a solution without a change of the API which could be adding something to know if the log_backend is up or not?

What is your thought on this?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Change the API :-)

Fix data_out_block_mode() to return the data correctly sent to RTT.
Before this fixes, it was always returning `lenght`, even in situation
where data have been dropped. This was leading to not having the dropped
messages warning displayed.

Fixes zephyrproject-rtos#21514

Signed-off-by: Xavier Chapron <[email protected]>
@@ -222,7 +222,7 @@ static int data_out_block_mode(u8_t *data, size_t length, void *ctx)
}
} while ((ret == 0) && host_present);

return ((ret == 0) && host_present) ? 0 : length;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Change the API :-)

@nashif nashif added the Stale label Sep 8, 2020
@github-actions github-actions bot closed this Sep 23, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Logging - strange behaviour with RTT on nRF53
7 participants