sys/log: Add optional support for sector bookmarks to optimize reading logs #3365
Conversation
vrahane
changed the title
vrahane
force-pushed
the
vipul/bmarks
branch
3 times, most recently
from
bf7d968 to
efdadf6
Compare
vrahane
force-pushed
the
vipul/bmarks
branch
7 times, most recently
from
deafc14 to
0e3bcee
Compare
- Add sector bookmarks for reading optimization - Retain older absolute bookmarks behavior - CLI: Add '-t' option in log_shell for measuring read time (cherry-picking Jerzy's commit) - CLI: Add '-b' option in log_shell for reading bookmarks
vrahane
force-pushed
the
vipul/bmarks
branch
from
0e3bcee to
142177c
Compare
There was a problem hiding this comment.
- Code will not build for FCB2
- It's not clear how to choose size for bookmarks array
- If suggested size is around number of sector of the FCB flash area, RAM usage can be an issue. For 384 sectors' FCB RAM usage is over 12KB
- There are places that use code and RAM space even if no bookmarks/sector-bookmarks are enabled
vrahane
force-pushed
the
vipul/bmarks
branch
4 times, most recently
from
3bcb976 to
8f26895
Compare
vrahane
force-pushed
the
vipul/bmarks
branch
3 times, most recently
from
39d40d1 to
9611300
Compare
vrahane
force-pushed
the
vipul/bmarks
branch
from
c3aeeb3 to
9b45dc3
Compare
When you addressed them it clearly does not mean they are resolved them |
|
Ok, whichever you feel is not done, please un-resolve it. |
vrahane
force-pushed
the
vipul/bmarks
branch
from
9b45dc3 to
25e4f20
Compare
vrahane
force-pushed
the
vipul/bmarks
branch
from
25e4f20 to
33f93fd
Compare
|
@kasjer I have tried to address all comments. Please let me know what you think ? |
There was a problem hiding this comment.
Tested with FCB2 and while it compiles it does not seems that functionality works.
I did not try to look what is wrong but dump from bookmark table is strange
compat> log -b
016463 0: index: 99 entry: 24003088 fr: 2400306c fe_sector: 0 fe_data_off: e62
016464 1: index: 98 entry: 2400309c fr: 2400306c fe_sector: 0 fe_data_off: df8
016467 2: index: 97 entry: 240030b0 fr: 2400306c fe_sector: 0 fe_data_off: d86
016474 3: index: 96 entry: 240030c4 fr: 2400306c fe_sector: 0 fe_data_off: d40
016481 4: index: 95 entry: 240030d8 fr: 2400306c fe_sector: 0 fe_data_off: cdc
016488 5: index: 94 entry: 240030ec fr: 2400306c fe_sector: 0 fe_data_off: c9a
016495 6: index: 93 entry: 24003100 fr: 2400306c fe_sector: 0 fe_data_off: c54
016502 7: index: 92 entry: 24003114 fr: 2400306c fe_sector: 0 fe_data_off: c17
016509 8: index: 91 entry: 24003128 fr: 2400306c fe_sector: 0 fe_data_off: baf
016516 9: index: 90 entry: 2400313c fr: 2400306c fe_sector: 0 fe_data_off: b5f
It does not look like bookmarks refer to separate sector as is the case for FCB
| @@ -231,7 +231,7 @@ ltfbu_init(const struct ltfbu_cfg *cfg) | |||
| TEST_ASSERT_FATAL(rc == 0); | |||
|
|
|||
| if (cfg->bmark_count > 0) { | |||
| log_fcb_init_bmarks(<fbu_fcb_log, ltfbu_bmarks, cfg->bmark_count); | |||
| log_fcb_init_bmarks(<fbu_fcb_log, ltfbu_bmarks, cfg->bmark_count, false); | |||
There was a problem hiding this comment.
This is the only place in mynewt repository where log_fcb_init_bmarks() is called. When I try to put similar code (except last argument is true) in actual code system crashes.
Is there a restriction on when this function should be called?
There was a problem hiding this comment.
Well, there is no restrictions as such, I called it on the fcb from the slinky app and that seemed to work. Where did you call it from ?
There was a problem hiding this comment.
This is test function called from main after
int
test_log_init(void)
{
const struct flash_area *fa;
struct fcb *fcbp;
int sector_count;
int rc;
if (flash_area_open(FLASH_AREA_TEST_LOG, &fa)) {
return SYS_EUNKNOWN;
}
flash_area_to_sectors(FLASH_AREA_TEST_LOG, §or_count, NULL);
test_log_sectors = calloc(sector_count, sizeof(*test_log_sectors));
flash_area_to_sectors(FLASH_AREA_TEST_LOG, §or_count, test_log_sectors);
test_log_fcb.fl_entries = 0;
fcbp = &test_log_fcb.fl_fcb;
fcbp->f_magic = 0x7EADBADF;
fcbp->f_version = g_log_info.li_version;
fcbp->f_sector_cnt = sector_count - 1;
fcbp->f_scratch_cnt = 1;
fcbp->f_sectors = test_log_sectors;
rc = fcb_init(fcbp);
if (rc) {
flash_area_erase(fa, 0, fa->fa_size);
rc = fcb_init(fcbp);
if (rc) {
return rc;
}
}
#if MYNEWT_VAL_LOG_FCB_SECTOR_BOOKMARKS
int bookmark_count = fcbp->f_sector_cnt + MYNEWT_VAL_LOG_FCB_NUM_ABS_BOOKMARKS;
test_log_bookmarks = malloc(bookmark_count * sizeof(*test_log_bookmarks));
log_fcb_init_bmarks(&test_log_fcb, test_log_bookmarks, bookmark_count, true);
#endif
rc = log_register("test_log", &test_log, &log_fcb_handler,
&test_log_fcb, LOG_SYSLEVEL);
return rc;
}Order of calls based on the only example found in unit tests except unit tests call to log_fcb_init_bmarks() has false as last argument:
- fcb_init()
- log_fcb_init_bmarks() <- crashes inside
- log_register()
sys/log/full/src/log_fcb_bmark.c
Outdated
| if (bset->lfs_size && bset->lfs_size > pos && pos != (bset->lfs_cap - 1)) { | ||
| memmove(&bset->lfs_bmarks[pos + 1], &bset->lfs_bmarks[pos], | ||
| sizeof(bset->lfs_bmarks[0]) * (bset->lfs_size - pos)); |
There was a problem hiding this comment.
This code keeps sector bookmarks sorted by index.
It does not look like any other place in the code takes advantage of this order. When bookmarks are search for match this order is not utilized.
Maybe there is not need to move chunk of memory every time when sector bookmark is inserted which seems to be the case since sector are scanned from the oldest one. So every sector bookmark result in memmove with increasing size.
There was a problem hiding this comment.
This was done because earlier absolute bookmarks could actually be in between the other bookmarks based on the index. Even now, insertion happens as pos 0 but, we could optimize it so that there is no memmove happening. Let me try it.
There was a problem hiding this comment.
Ok, I did optimize the code quite a bit. Please take a look. As per the review comment I have removed memmove.
| * If sector bookmarks are enabled, buffer should be big enough | ||
| * to accomodate bookmarks for the entire flash area that is allocated | ||
| * for the FCB log, i,e; sizeof(struct log_fcb_bmark) * | ||
| * my_log.fl_fcb.f_sector_cnt + MYNEWT_VAL(LOG_FCB_NUM_ABS_BOOKMARKS) |
There was a problem hiding this comment.
It can't stay like this. The function should return an error if buffer is too small and not just crash later on. But actually it would be better if it can work with smaller buffers as well and e.g. place bookmark every n-th sector or just skip bookmarks that don't fit in the buffer.
There was a problem hiding this comment.
That is possible but it complicates the code further. Just failing is a better approach. The user should know what they are doing. What if they have a bigger buffer ? Then we will have to handle that too. I would like to keep it a bit restricted in its usage.
There was a problem hiding this comment.
It's not complicated. It's just a simple if statement added to log_fcb_init_sector_bmarks so log_fcb_add_bmark is not called for every sector.
You can simply calculate max number of bookmarks from the buffer size and then either add at most that number of bookmarks or, even better, divide number of sectors by that number and insert bookmark every n-th sector only so it doesn't overflow buffer. I don't ask you to handle any special cases, e.g. if the buffer is too big then it will simply have some free space left.
There was a problem hiding this comment.
Ok, let me give it a shot.
There was a problem hiding this comment.
@andrzej-kaczmarek Ok, I have added support for this. Please take a look. I am going to exercise it little bit more to make sure there are no edge cases I have forgotten.
vrahane
force-pushed
the
vipul/bmarks
branch
from
ea6b6dc to
98f2220
Compare
vrahane
force-pushed
the
vipul/bmarks
branch
2 times, most recently
from
5471eaa to
b2fb7fc
Compare
vrahane
force-pushed
the
vipul/bmarks
branch
from
b2fb7fc to
6beb34c
Compare
|
@kasjer and @andrzej-kaczmarek build failures are unrelated. |
|
This time I did not look at the code just tested it on the entirely full fcb log on 1MB spi flash with 6 absolute bookmarks. Last 6 elements are for absolute bookmarks I guess Now duplicate entry is present in absolute bookmark space (previously it was not the case) Walk is fast as expected Times seems to vary depending on index, grater index -> slower walk And here is measurements when sector bookmarks are off, this is single session Without sector bookmarks (absolute bookmarks are enabled) timing seems reasonable. |
|
@kasjer I do not see the issues you mentioned above with my setup with default number of absolute bookmarks and using the sector count for sector bookmarks. Attaching the coolterm output. This is my initialization code: |
|
@vrahane in your logs bookmarks look ok, in my case first entry looks strange: This strange element at the beginning is always there. I have not checked why it's there but it probably could explain why sector bookmarks are not used |
|
@kasjer it seems |
|
I also tried with 6 absolute bookmarks. It works fine. |
Yes, after correction to sector_count measured times are fast as expected |
|
I am curious what timings do you see on your device ? |
For mixed bookmarks:
0->sector_cntof the flash area in the array.sector_cnt->LOG_FCB_NUM_ABS_BMARKS(2 by default)Several tests were performed: