Add optional tracing to sleep manager lock/unlock #6142

ghost · 2018-02-20T13:41:16Z

Description

Add tracing output to console to track when drivers lock and unlock deep sleep. Tracing output is enabled by configuring the 'MBED_SLEEP_TRACING_ENABLED ' at compile time.

Wrapped sleep_manager_lock/sleep_manager_unlock in a macro to conditionally call tracing functions when 'MBED_SLEEP_TRACING_ENABLED' is set.
Define a global structure to track driver names and how many locks they hold in the sleep manager.

Status

IN DEVELOPMENT

Todos

Tests
Documentation

Steps to test or reproduce

Define the SLEEP_PROFILING_ENABLED macro in an application, eg:

{
  "config": {
    "sleep_profiling_enabled": {
      "value": 1,
      "macro_name": "SLEEP_PROFILING_ENABLED"
    }
  }
}

cause deep sleep to be locked/unlock by calling a driver that locks it:

void trigger(){}
int main()
{
  Timer* timer = new Timer();
  timer->start();

  Ticker* ticker = new Ticker();
  ticker->attach(&trigger, 500);

  sleep();
}

output should show:

LOCK: Timer.cpp, ln: 50, lock count: 1
LOCK: Ticker.h, ln: 120, lock count: 2
LOCK: mbed_rtx_idle.cpp, ln: 227, lock count: 3
UNLOCK: mbed_rtx_idle.cpp, ln: 229, lock count: 2
[id: Timer., count: 1]
[id: Ticker, count: 1]

amq · 2018-02-20T23:14:27Z

It would be nice if the print function was configurable, so that e.g. tr_info() could be used instead of printf()

0xc0170 · 2018-02-21T09:12:25Z

It would be nice if the print function was configurable, so that e.g. tr_info() could be used instead of printf()

Had the same comment to be added here. @deepikabhavnani is working on tracing lib, but that might take a while. we have some logs in this codebase in some parts (not yet unified), but rather than own config would be easier to align this on something that it's been already used, then the new tracing lib would come and refactor this? @scartmell-arm please chat with @deepikabhavnani

ghost · 2018-02-21T14:04:14Z

Yes, the intention was to use the tracing library with this, which as far as I can tell should just require replacing the printfs with the trace macros/functions that get added.

deepikabhavnani · 2018-02-21T14:24:52Z

Printing filename and line number was part of the logging implementation and was removed recently for string based implementation, will that be required here?

ghost · 2018-02-21T14:32:15Z

The line number isn't important and the filename output isn't required as part of the interface. The FILE macro is used as an identifier to track which drivers have called the lock/unlock functions, so it isn't required as part of the interface as it's already accessible when printing the lock statistics.

amq · 2018-02-22T22:17:22Z

For consistency across mbed-os, the macro could be named MBED_SLEEP_STATS_ENABLED, similarly to:

MBED_TRAP_ERRORS_ENABLED
MBED_HEAP_STATS_ENABLED
MBED_STACK_STATS_ENABLED

It would be also helpful if sleep_tracker_print_stats() could be used manually, otherwise there often may be an unmanagable stream of

LOCK: mbed_wait_api_rtos.cpp, ln: 42, lock count: 3
UNLOCK: mbed_wait_api_rtos.cpp, ln: 44, lock count: 2
[id: Timer., count: 1]
[id: Ticker, count: 1]

bulislaw

I'm not actually sure why sleep manager lives in HAL, it's a driver. @SenRamakri do you think we could move it to drivers?

bulislaw · 2018-02-26T09:18:00Z

hal/mbed_sleep_manager.c

+// Number of drivers that can be stored in the structure
+#define STATISTIC_COUNT  10
+
+typedef struct __PACKED sleep_statistic {


Remove the __PACKED it doesn't make any difference here and generally I'm sceptical about use of packed structures, it may have negative effects on performance and put pressure on the bus with unaligned accesses.

bulislaw · 2018-02-26T09:32:54Z

platform/mbed_sleep.h

+        sleep_tracker_unlock(__FILE__, __LINE__);   \
+    } while (0);
+
+void sleep_tracker_lock(const char *const filename, int line);


Why do we need it here?

It's sort of the other way around, if you use serial then the deep sleep is disabled.

I am thinking of case, when no device/peripheral has locked deep sleep, so device can actually enter deep sleep.

Last unlock, sleep_manager_unlock_deep_sleep_internal() - Counter goes down to zero.

sleep_tracker_unlock(__FILE__, __LINE__); - This will enable UART.

So it will lock deep sleep again unlock again.

Will this be recursive? Correct me if I am missing anything or interpreting it wrongly.

This sounds like it could be an issue, but I've never seen it happen. I've not seen UART lock the deep sleep while running the tracker, perhaps it locks it through some other means.

geky · 2018-02-26T17:34:17Z

We currently have a distinction between "tracing" and "stats". "Tracing" utilities continuously log data on relevant events, whereas "stats" utilities allow you to manually grab snapshots about the current state.

Looking at this pr, MBED_SLEEP_TRACING_ENABLED would probably be a better config name.

Building on @amq comment, it'd be useful to have the MBED_SLEEP_STATS_ENABLED side as well. If you're interested this would require adding a mbed_stats_deep_sleep_get sort of function that fills out a struct with relevant data. Here's the heap/stack stats for example:
https://github.com/ARMmbed/mbed-os/blob/master/platform/mbed_stats.h

This would be useful for tools that report stats on their own tick and profiling tests in the CI.

cc @kegilbert, @c1728p9

deepikabhavnani · 2018-02-26T18:08:39Z

platform/mbed_sleep.h

@@ -64,6 +64,34 @@ extern "C" {
 * }
 * @endcode
 */
+#ifdef MBED_SLEEP_STATS_ENABLED
+
+#define sleep_manager_lock_deep_sleep()           \


How deep is sleep for peripherals at present? Do we disable clock for UART in any target device?

It's sort of the other way around, if you use serial then the deep sleep is disabled. So this info is theoretical and @scartmell-arm will create a docs how to interpret that data.

SenRamakri · 2018-02-27T00:05:55Z

hal/mbed_sleep_manager.c

+
+    printf("UNLOCK: %s, ln: %i, lock count: %u\r\n", stripped_path, line, deep_sleep_lock);
+    sleep_tracker_print_stats();
+    printf("\r\n");


Please move this printf inside sleep_tracker_print_stats, makes it look cleaner.

deepikabhavnani · 2018-02-27T05:17:42Z

platform/mbed_sleep.h

+    do                                            \
+    {                                             \
+        sleep_manager_lock_deep_sleep_internal(); \
+        sleep_tracker_lock(__FILE__, __LINE__);   \


You can use __MODULE__ for ARM and __BASE_FILE__ for GCC_ARM instead of __FILE__ to get just filename without path details.

--no_path_in_file_macros option in IAR is to exclude path from __BASE_FILE__, but I have not tested that.

bulislaw · 2018-02-27T09:48:12Z

Building on @amq comment, it'd be useful to have the MBED_SLEEP_STATS_ENABLED side as well. If you're interested this would require adding a mbed_stats_deep_sleep_get sort of function that fills out a struct with relevant data. Here's the heap/stack stats for example:
https://github.com/ARMmbed/mbed-os/blob/master/platform/mbed_stats.h

This would be useful for tools that report stats on their own tick and profiling tests in the CI.

cc @kegilbert, @c1728p9

We are dangerously close to the code freeze, lets park this one for now.

bulislaw · 2018-02-28T12:48:41Z

Guys the code freeze is coming please rereview: @deepikabhavnani @SenRamakri @geky

ghost · 2018-02-28T13:23:01Z

/morph build

mbed-ci · 2018-02-28T13:40:41Z

Build : SUCCESS

Build number : 1295
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/6142/

Triggering tests

/morph test
/morph uvisor-test
/morph export-build
/morph mbed2-build

deepikabhavnani · 2018-02-28T14:50:10Z

hal/mbed_sleep_manager.c

+
+static sleep_statistic_t sleep_stats[STATISTIC_COUNT];
+
+static const char* strip_path(const char* const filename)


All this runtime processing can be avoided, if we use proper compile time pre-processing macros (__MODULE__ for ARM and __BASE_FILE__ for GCC_ARM). Not blocking the release, but please update this in next PR.

That's fine for ARM and GCC, but the only way to do it for IAR seems to be enabling --no_path_in_file_macros which seems excessive unless it can be applied selectively to this file.

--no_path_in_file_macros : I guess we will be adding this anyways in future for unified tracing.

Instead of using filename can we use function name of the caller( the caller will pass __FUNCTION__ ), that will avoid all these processing as well, does that work?

I think using __BASE_FILE__ would work better, it can be added when this is altered to use the tracing.

Using __FUNCTION__ might be problematic. The names of the functions that call lock and unlock are going to be different so tracking which unlock is associated with each lock would be complicated, multiple drivers are also likely to have the same function names that lock/unlock the sleep manager, and it's difficult to identify which driver locked the sleep manager based on the function name alone

mbed-ci · 2018-02-28T15:50:57Z

Exporter Build : SUCCESS

Build number : 956
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/exporter/6142/

mbed-ci · 2018-02-28T16:24:35Z

Test : FAILURE

Build number : 1081
Test logs :http://mbed-os-logs.s3-website-us-west-1.amazonaws.com/?prefix=logs/6142/1081

ghost · 2018-03-01T17:39:32Z

Heh, should all be sorted now, as indicated fixing merge conflicts is not my forte.

ghost · 2018-03-01T18:38:52Z

/morph build

mbed-ci · 2018-03-01T19:24:39Z

Build : SUCCESS

Build number : 1316
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/6142/

Triggering tests

/morph test
/morph uvisor-test
/morph export-build
/morph mbed2-build

cmonr · 2018-03-01T19:26:45Z

@bulislaw Is the intention for this to make it into 5.8-rc1? I'm reading conflicting message from you:
#6142 (comment) vs #6142 (comment)
Marking this as 5.8 for now.

@scartmell-arm A friendly reminder that only maintainers should be triggering builds, especially this close to generating a release PR.

cmonr · 2018-03-01T19:37:11Z

@scartmell-arm Do you run tests or at least do a sanity compilation in between commits? I'm wondering how those merge errors got into the history in the first place, especially since they're so far apart from each other (2 days vs 6 days).

ghost · 2018-03-01T19:53:12Z

@cmonr No, I rebased all seven commits about 1-2 hours ago, the merge conflict happened in one of the earlier ones and I forgot to commit the manual merge before continuing. The conflict only happened ~3 hours ago when #6230 got merged and the file I was committing to got moved around.

mbed-ci · 2018-03-01T20:15:08Z

Exporter Build : SUCCESS

Build number : 976
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/exporter/6142/

bulislaw · 2018-03-01T20:52:21Z

Yes, it's 5.8 the #6142 (comment) was about Chrises comment and adding extra features.

cmonr · 2018-03-01T20:52:38Z

@bulislaw @sg- @deepikabhavnani @SenRamakri @geky @c1728p9 Any final words on this PR while there's still a chance?

SenRamakri · 2018-03-01T21:49:42Z

hal/mbed_sleep_manager.c

+    core_util_atomic_decr_u8(&stat->count, 1);
+
+    printf("UNLOCK: %s, ln: %i, lock count: %u\r\n", stripped_path, line, deep_sleep_lock);
+    sleep_tracker_print_stats();


I think its an overkill to print the stats on every unlock call, particularly when we are printing the LOCK/UNLOCK info in the sleep_tracker_lock/unlock calls. But, I'm not going to block this PR for that as its not a major blocker, but you may want to re-think on that.

mbed-ci · 2018-03-01T22:09:39Z

Test : FAILURE

Build number : 1100
Test logs :http://mbed-os-logs.s3-website-us-west-1.amazonaws.com/?prefix=logs/6142/1100

sg- · 2018-03-01T23:26:45Z

hal/mbed_sleep_manager.c

+
+    core_util_atomic_incr_u8(&stat->count, 1);
+
+    printf("LOCK: %s, ln: %i, lock count: %u\r\n", stripped_path, line, deep_sleep_lock);


Why is this printf and not debug? If debug it could be stripped from a release build.

sg- · 2018-03-01T23:26:53Z

hal/mbed_sleep_manager.c

+
+    core_util_atomic_decr_u8(&stat->count, 1);
+
+    printf("UNLOCK: %s, ln: %i, lock count: %u\r\n", stripped_path, line, deep_sleep_lock);


Why is this printf and not debug? If debug it could be stripped from a release build.

bulislaw · 2018-03-02T00:37:42Z

/morph build

mbed-ci · 2018-03-02T01:05:08Z

Build : SUCCESS

Build number : 1319
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/6142/

Triggering tests

/morph test
/morph uvisor-test
/morph export-build
/morph mbed2-build

mbed-ci · 2018-03-02T02:43:11Z

Exporter Build : SUCCESS

Build number : 980
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/exporter/6142/

mbed-ci · 2018-03-02T03:24:28Z

Test : SUCCESS

Build number : 1104
Test logs :http://mbed-os-logs.s3-website-us-west-1.amazonaws.com/?prefix=logs/6142/1104

ghost

LGTM

adbridge

Looks like the review comments have been completed and Steve has approved them. Thus approving this PR overall in order to merge.

mbed-ci · 2018-08-02T16:55:43Z

Exporter Build : FAILURE

Build number : 2363
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/exporter/6142/

0xc0170 added the needs: review label Feb 20, 2018

0xc0170 requested a review from bulislaw February 20, 2018 13:48

bulislaw requested review from senthilr and SenRamakri and removed request for senthilr February 26, 2018 08:52

bulislaw suggested changes Feb 26, 2018

View reviewed changes

bulislaw requested review from 0xc0170, deepikabhavnani and geky February 26, 2018 09:40

deepikabhavnani reviewed Feb 26, 2018

View reviewed changes

deepikabhavnani requested a review from c1728p9 February 26, 2018 18:15

SenRamakri reviewed Feb 27, 2018

View reviewed changes

deepikabhavnani reviewed Feb 27, 2018

View reviewed changes

0xc0170 changed the title ~~Added optional tracing to sleep manager lock/unlock~~ Add optional tracing to sleep manager lock/unlock Feb 27, 2018

bulislaw previously approved these changes Feb 27, 2018

View reviewed changes

deepikabhavnani reviewed Feb 28, 2018

View reviewed changes

deepikabhavnani previously approved these changes Feb 28, 2018

View reviewed changes

Fix merge conflict mishap

206cc29

cmonr added the release-version: 5.8.0-rc1 label Mar 1, 2018

SenRamakri reviewed Mar 1, 2018

View reviewed changes

SenRamakri previously approved these changes Mar 1, 2018

View reviewed changes

sg- reviewed Mar 1, 2018

View reviewed changes

Fix review comments and merge issues

d6f57bc

bulislaw dismissed SenRamakri’s stale review via d6f57bc March 2, 2018 00:29

ghost commented Mar 2, 2018

View reviewed changes

adbridge self-requested a review March 2, 2018 10:52

adbridge approved these changes Mar 2, 2018

View reviewed changes

adbridge removed the needs: review label Mar 2, 2018

adbridge merged commit a137444 into ARMmbed:master Mar 2, 2018

AriParkkila mentioned this pull request Mar 2, 2018

Mbed OS cellular connectivity #6082

Merged

ghost deleted the feature-deep-sleep-tracing branch December 5, 2018 16:48


		static sleep_statistic_t sleep_stats[STATISTIC_COUNT];

		static const char* strip_path(const char* const filename)


		core_util_atomic_incr_u8(&stat->count, 1);

		printf("LOCK: %s, ln: %i, lock count: %u\r\n", stripped_path, line, deep_sleep_lock);


		core_util_atomic_decr_u8(&stat->count, 1);

		printf("UNLOCK: %s, ln: %i, lock count: %u\r\n", stripped_path, line, deep_sleep_lock);

Add optional tracing to sleep manager lock/unlock #6142

Add optional tracing to sleep manager lock/unlock #6142

Uh oh!

Conversation

ghost commented Feb 20, 2018 • edited by deepikabhavnani Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Status

Todos

Steps to test or reproduce

Uh oh!

amq commented Feb 20, 2018

Uh oh!

0xc0170 commented Feb 21, 2018

Uh oh!

ghost commented Feb 21, 2018

Uh oh!

deepikabhavnani commented Feb 21, 2018

Uh oh!

ghost commented Feb 21, 2018

Uh oh!

amq commented Feb 22, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

bulislaw left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

deepikabhavnani Feb 27, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

geky commented Feb 26, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

deepikabhavnani Feb 27, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bulislaw commented Feb 27, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

bulislaw commented Feb 28, 2018

Uh oh!

ghost commented Feb 28, 2018

Uh oh!

mbed-ci commented Feb 28, 2018

Triggering tests

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mbed-ci commented Feb 28, 2018

Uh oh!

mbed-ci commented Feb 28, 2018

Uh oh!

ghost commented Mar 1, 2018

Uh oh!

ghost commented Mar 1, 2018

Uh oh!

mbed-ci commented Mar 1, 2018

Triggering tests

Uh oh!

ghost commented Feb 20, 2018 •

edited by deepikabhavnani

Loading

amq commented Feb 22, 2018 •

edited

Loading

deepikabhavnani Feb 27, 2018 •

edited

Loading

deepikabhavnani Feb 27, 2018 •

edited

Loading

bulislaw commented Feb 27, 2018 •

edited

Loading

ghost commented Mar 1, 2018 •

edited by ghost

Loading