Skip to content

tests/pthread_rwlock: run the test in CI#11688

Merged
jcarrano merged 2 commits intoRIOT-OS:masterfrom
cladmi:pr/tests/pthread_rwlock/enable_in_ci
Aug 21, 2019
Merged

tests/pthread_rwlock: run the test in CI#11688
jcarrano merged 2 commits intoRIOT-OS:masterfrom
cladmi:pr/tests/pthread_rwlock/enable_in_ci

Conversation

@cladmi
Copy link
Copy Markdown
Contributor

@cladmi cladmi commented Jun 13, 2019

Contribution description

Enable running the test as the test is available.

Testing procedure

The test must be successfully executed by CI (check the listed tests).

Issues/PRs references

Found it was not enabled while working on #11680
I blacklisted native due to #11691

@cladmi cladmi added Area: tests Area: tests and testing framework CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR CI: run tests If set, CI server will run tests on hardware for the labeled PR CI: disable test cache If set, CI will always run all tests regardless of whether they have been run successfully before labels Jun 13, 2019
@cladmi cladmi added this to the Release 2019.07 milestone Jun 13, 2019
@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Jun 13, 2019

The test failed on samr21-xpro:llvm but it may be a dynamic issue. It works on my machine with the same conditions

TOOLCHAIN=llvm RIOT_TERMINAL=picocom BUILD_IN_DOCKER=1 DOCKER="sudo docker" BOARD=samr21-xpro make -C tests/pthread_rwlock/ flash test

@cladmi cladmi force-pushed the pr/tests/pthread_rwlock/enable_in_ci branch from 778f130 to 9e835a8 Compare July 12, 2019 16:53
@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Jul 12, 2019

Rebased to use TESTS_ON_CI_BLACKLIST #11743.
I blacklisted native due to #11691

@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Jul 15, 2019

Looking more at the code and the output, I think this is just a non de-scheduling aware test

main(): This is RIOT! (Version: buildtest)
START
start
d3 (prio=8): sleep for     6423 µs.
start
d4 (prio=8): sleep for    46739 µs.
start
start
start
start
starr3 (prio=8): 0: read  <-  0 (correct = 1)
d3 (prio=8): sleep for    12174 µs.
prstart
r4 (prio=8): 0: read  <-  0 (correct = 1)
d4 (prio=8): sleep for    99314 µs.
d8 (prio=8): sleep for   225078 µs.
w8 (prio=8): 0: write ->  1 (correct = 1)
d8 (prio=8): sleep for   127208 µs.
d3 (prio=8): sleep for    41928 µs.
d4 (prio=8): sleep for     4969 µs.
d5 (prio=9): sleep for    29410 µs.

@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Jul 15, 2019

This now added a mutex around the outputs. It should prevent any text mixing during the execution.

@fjmolinas fjmolinas self-requested a review August 2, 2019 14:45
@fjmolinas
Copy link
Copy Markdown
Contributor

Looking more at the code and the output, I think this is just a non de-scheduling aware test

@cladmi do you have a way to reproduce locally?


/* The test assumes that 'printf/puts' are non interruptible operations
* use a mutex to guarantee it */
static mutex_t stdout_mutex = MUTEX_INIT;
Copy link
Copy Markdown
Contributor

@fjmolinas fjmolinas Aug 8, 2019

Choose a reason for hiding this comment

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

Couldn't this be generalized? I would imagine more use cases where interrupted prints can screw up a tests. #11818 deactivated ISR to achieve a similar result.

/* Sometimes, udhcp output messes up the following printfs. That
* confuses the test script. As a workaround, just disable interrupts
* for a while.
*/
irq_disable();

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Deactivated ISR do not work if the test is using DMA printfs.
As we cannot know in RIOT if interrupt are disabled, the dma implementation of uart_write cannot do an disabled interrupt safe implementation.

And printing is really slow so disabling interrupts for a long time seems bad.

I was talking about having a console_lock in the dma print, that could also be useful when you want a block to be printed as a transaction that could even be done in multiple printf by explicitly taking the lock.
#10800 (comment)
It would need to be a rlock though.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

I was talking about having a console_lock in the dma print, that could also be useful when you want a block to be printed as a transaction that could even be done in multiple printf by explicitly taking the lock.
#10800 (comment)
It would need to be a rlock though.

+1, even if it would need rlock, I think it would make sense to have a feature like this for testing. Do you have plans on working on this soon? If not we can go with the local implementation for now, but I wouldn't want it to start being replicated every time we need to make sure prints are correctly going threw.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Edit: in the dma print discussion

No plans to work on it soon, I also have no idea how it can be done at the C library level "automatically" :/

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

An implementation could be to define a console_lock rmutex and locked_printf, locked_puts macros or functions (and others).

But it would only solve the case where they are explicitly used, so more in the tests applications. It would be enough as long as there is no other debug outputs. So not when using the gnrc debug module at the same time, or drivers putting debug messages for example.

If this is enough I could try putting some time on it.

Managing to make it the default could be another task and split in a dedicated module like "printf_auto_rlock".

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

An implementation could be to define a console_lock rmutex and locked_printf, locked_puts macros or functions (and others).

But it would only solve the case where they are explicitly used, so more in the tests applications. It would be enough as long as there is no other debug outputs. So not when using the gnrc debug module at the same time, or drivers putting debug messages for example.

Hmm, thats true. Many of the use cases I can think fall in the printf_auto_rlock case. I think it makes more sense working on "printf_auto_rlock", I'll think it over a little more and see if I can find more use cases, but if not we can go with this as is.

@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 12, 2019

Looking more at the code and the output, I think this is just a non de-scheduling aware test

@cladmi do you have a way to reproduce locally?

I am not sure, if I remember correctly, my comment in #11688 (comment) was copied from the murdock output.

I could try finding one failing node on IoT-LAB if it is board specific.

@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 12, 2019

I do not have a failing test here, but the mixed output.
It does not fail as here the start is not cut.

IOTLAB_NODE=samr21-1.saclay.iot-lab.info BOARD=samr21-xpro make --no-print-directory -C tests/pthread_rwlock/ test
ssh -t [email protected] 'socat - tcp:samr21-1.saclay.iot-lab.info:20000'
main(): This is RIOT! (Version: 2019.10-devel-371-g700b12)
START
start
d3 (prio=8): sleep for    38522 µs.
start
d4 (prio=8): sleep for    52348 µs.
start
start
start
start
start
start
r3 (prio=8): 0: read  <-  0 (correct = 1)
d3 (prio=8): sleep for    76641 µs.
r4 (prio=8): 0: read  <-  0 (correct = 1)
d4 (prio=8): sleep for    37538 µs.
d8 (prio=8): sleep for   224298 µs.
w8 (prio=8): 0: write ->  1 (correct = 1)
d8 (prio=8): sleep for    66418 µs.
d4 (prio=8): sleep for     9029 µs.
d3 (prio=8): sleep for    85173 µs.
d5 (prio=9): sleep for    58755 µs.
d6 (prio=9): sleep for   r4 (prio=8): 1: read  <-  1 (correct = 1)
d4 (prio=8): sleep for     8467 µs.
  8467 µs.
d7 (prio=9): sleep for     2232 µs.
r7 (prio=9): 0: read4 (prio=8): sleep for    65593 µs.
for    65593 µs.
= 1)
d7 (prio=9): sleep for    21694 µs.
r5 (prio=9): 0: read  <-  1 (correct = 1)
d5 (prio=9): sleep for    33500 µs.
r3 (prio=8): 1: read  <-  1 (correct = 1)
d3 (prio=8): sleep for    99426 µs.
r4 (prio=8): 2: read  <-  1 (correct = 1)

And there is no mixed output with this PR (rebased on master for good measure).

IOTLAB_NODE=samr21-1.saclay.iot-lab.info BOARD=samr21-xpro make --no-print-directory -C tests/pthread_rwlock/ test
IOTLAB_NODE=samr21-1.saclay.iot-lab.info BOARD=samr21-xpro make --no-print-directory -C tests/pthread_rwlock/ test
ssh -t [email protected] 'socat - tcp:samr21-1.saclay.iot-lab.info:20000'
main(): This is RIOT! (Version: 2019.10-devel-373-gc796f-HEAD)
START
start
d3 (prio=8): sleep for    38522 µs.
start
d4 (prio=8): sleep for    52348 µs.
start
start
start
start
start
start
r3 (prio=8): 0: read  <-  0 (correct = 1)
d3 (prio=8): sleep for    76641 µs.
r4 (prio=8): 0: read  <-  0 (correct = 1)
d4 (prio=8): sleep for    37538 µs.
d8 (prio=8): sleep for   224298 µs.
w8 (prio=8): 0: write ->  1 (correct = 1)
d8 (prio=8): sleep for    66418 µs.
d4 (prio=8): sleep for     9029 µs.
d3 (prio=8): sleep for    85173 µs.
d5 (prio=9): sleep for    58755 µs.
d6 (prio=9): sleep for    71257 µs.
r4 (prio=8): 1: read  <-  1 (correct = 1)
d4 (prio=8): sleep for     8467 µs.
d7 (prio=9): sleep for     2232 µs.
r7 (prio=9): 0: read  <-  1 (correct = 1)
d4 (prio=8): sleep for    65593 µs.
d7 (prio=9): sleep for    21694 µs.
r5 (prio=9): 0: read  <-  1 (correct = 1)
d5 (prio=9): sleep for    33500 µs.
r3 (prio=8): 1: read  <-  1 (correct = 1)
d3 (prio=8): sleep for    99426 µs.
r4 (prio=8): 2: read  <-  1 (correct = 1)
d4 (prio=8): sleep for    33472 µs.
r6 (prio=9): 0: read  <-  1 (correct = 1)
d8 (prio=8): sleep for    95568 µs.
d6 (prio=9): sleep for    20605 µs.
w8 (prio=8): 1: write ->  2 (correct = 1)
d8 (prio=8): sleep for   132024 µs.
d4 (prio=8): sleep for    59431 µs.
d3 (prio=8): sleep for    61553 µs.
r4 (prio=8): 3: read  <-  2 (correct = 1)
d4 (prio=8): sleep for    62433 µs.
r3 (prio=8): 2: read  <-  2 (correct = 1)
d3 (prio=8): sleep for    64593 µs.
d9 (prio=9): sleep for   124371 µs.
w9 (prio=9): 0: write ->  3 (correct = 1)
d8 (prio=8): sleep for   122850 µs.
d9 (prio=9): sleep for   123980 µs.
w8 (prio=8): 2: write ->  4 (correct = 1)
d8 (prio=8): sleep for    60968 µs.
d4 (prio=8): sleep for    14187 µs.
d3 (prio=8): sleep for    79138 µs.
r4 (prio=8): 4: read  <-  4 (correct = 1)
d4 (prio=8): sleep for    95285 µs.
r3 (prio=8): 3: read  <-  4 (correct = 1)
d3 (prio=8): sleep for     9541 µs.
d8 (prio=8): sleep for     2364 µs.
w8 (prio=8): 3: write ->  5 (correct = 1)
d8 (prio=8): sleep for   175790 µs.
d10 (prio=9): sleep for   283653 µs.
done
w10 (prio=9): 0: write ->  6 (correct = 1)
d3 (prio=8): sleep for    10485 µs.
d10 (prio=9): sleep for   115472 µs.
r3 (prio=8): 4: read  <-  6 (correct = 1)
d3 (prio=8): sleep for     4856 µs.
d8 (prio=8): sleep for   217110 µs.
done
w8 (prio=8): 4: write ->  7 (correct = 1)
d8 (prio=8): sleep for   198446 µs.
d7 (prio=9): sleep for    50644 µs.
d5 (prio=9): sleep for     3259 µs.
d6 (prio=9): sleep for    41624 µs.
r5 (prio=9): 1: read  <-  7 (correct = 1)
d5 (prio=9): sleep for    66578 µs.
r6 (prio=9): 1: read  <-  7 (correct = 1)
d6 (prio=9): sleep for    37296 µs.
r7 (prio=9): 1: read  <-  7 (correct = 1)
d7 (prio=9): sleep for    18047 µs.
d9 (prio=9): sleep for   286119 µs.
done
w9 (prio=9): 1: write ->  8 (correct = 1)
d9 (prio=9): sleep for    29550 µs.
d10 (prio=9): sleep for   245199 µs.
w10 (prio=9): 1: write ->  9 (correct = 1)
d10 (prio=9): sleep for   168398 µs.
d5 (prio=9): sleep for    15265 µs.
d7 (prio=9): sleep for    83556 µs.
d6 (prio=9): sleep for    54845 µs.
r5 (prio=9): 2: read  <-  9 (correct = 1)
d5 (prio=9): sleep for    43866 µs.
r6 (prio=9): 2: read  <-  9 (correct = 1)
d6 (prio=9): sleep for     2657 µs.
r7 (prio=9): 2: read  <-  9 (correct = 1)
d7 (prio=9): sleep for    66501 µs.
d9 (prio=9): sleep for   233295 µs.
w9 (prio=9): 2: write -> 10 (correct = 1)
d9 (prio=9): sleep for   119232 µs.
d5 (prio=9): sleep for    98721 µs.
d6 (prio=9): sleep for    84466 µs.
d7 (prio=9): sleep for    69290 µs.
r7 (prio=9): 3: read  <- 10 (correct = 1)
d7 (prio=9): sleep for    16133 µs.
r6 (prio=9): 3: read  <- 10 (correct = 1)
d6 (prio=9): sleep for    66307 µs.
r5 (prio=9): 3: read  <- 10 (correct = 1)
d5 (prio=9): sleep for     8080 µs.
d10 (prio=9): sleep for   165735 µs.
w10 (prio=9): 2: write -> 11 (correct = 1)
d10 (prio=9): sleep for    73752 µs.
d7 (prio=9): sleep for    31103 µs.
d5 (prio=9): sleep for    68087 µs.
r7 (prio=9): 4: read  <- 11 (correct = 1)
d7 (prio=9): sleep for    16409 µs.
done
r5 (prio=9): 4: read  <- 11 (correct = 1)
d5 (prio=9): sleep for    61001 µs.
d9 (prio=9): sleep for     2967 µs.
w9 (prio=9): 3: write -> 12 (correct = 1)
d9 (prio=9): sleep for     2346 µs.
d6 (prio=9): sleep for    25155 µs.
r6 (prio=9): 4: read  <- 12 (correct = 1)
d6 (prio=9): sleep for    52469 µs.
d10 (prio=9): sleep for   145395 µs.
done
done
w10 (prio=9): 3: write -> 13 (correct = 1)
d10 (prio=9): sleep for   191662 µs.
d9 (prio=9): sleep for   262617 µs.
w9 (prio=9): 4: write -> 14 (correct = 1)
d9 (prio=9): sleep for   182958 µs.
d10 (prio=9): sleep for   118929 µs.
w10 (prio=9): 4: write -> 15 (correct = 1)
d10 (prio=9): sleep for   154684 µs.
done
done
SUCCESS

@cladmi cladmi force-pushed the pr/tests/pthread_rwlock/enable_in_ci branch from 6170862 to 48a4737 Compare August 12, 2019 10:25
@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 12, 2019

I re-ordered the commits to have the fix before enabling testing.

@fjmolinas
Copy link
Copy Markdown
Contributor

I do not have a failing test here, but the mixed output.
It does not fail as here the start is not cut.

That's enough for me, I can see why the issue can arise and it is present in the PR comment.

@fjmolinas
Copy link
Copy Markdown
Contributor

Ok there is clearly an issue with tests/nordic_softdevice/nrf52dk:gnu its failing repeatedly on PR's that run tests on HW. Lets wait for #11995

@fjmolinas fjmolinas added CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR and removed CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR labels Aug 12, 2019
@tcschmidt
Copy link
Copy Markdown
Member

So #11995 is merged, @fjmolinas ?

Copy link
Copy Markdown
Contributor

@jcarrano jcarrano left a comment

Choose a reason for hiding this comment

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

I'm almost fine with this, except for uncontained multi-line macros. It is not terrible, but it gives a bad example to future contributors.

static mutex_t stdout_mutex = MUTEX_INIT;

#define PRINTF(FMT, ...) \
mutex_lock(&stdout_mutex); \
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Suggested change
mutex_lock(&stdout_mutex); \
do { mutex_lock(&stdout_mutex); \

sched_active_thread->priority, \
(int)__VA_ARGS__)
(int)__VA_ARGS__); \
mutex_unlock(&stdout_mutex)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Suggested change
mutex_unlock(&stdout_mutex)
mutex_unlock(&stdout_mutex) \
} while (0);

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

I did it without the terminating ;.

(int)__VA_ARGS__); \
mutex_unlock(&stdout_mutex)

#define PUTS(s) \
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Suggested change
#define PUTS(s) \
#define PUTS(s) do { \

#define PUTS(s) \
mutex_lock(&stdout_mutex); \
puts(s); \
mutex_unlock(&stdout_mutex)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Suggested change
mutex_unlock(&stdout_mutex)
mutex_unlock(&stdout_mutex) \
} while (0);

@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 20, 2019

Indeed, they definitely need a do while. I will fix this.

@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 20, 2019

I also indented to match the normal style in the source code.

Copy link
Copy Markdown
Contributor

@jcarrano jcarrano left a comment

Choose a reason for hiding this comment

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

Ok. Squash pls.

@jcarrano jcarrano added CI: needs squashing Commits in this PR need to be squashed; If set, CI systems will mark this PR as unmergable and removed CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR labels Aug 20, 2019
@cladmi cladmi force-pushed the pr/tests/pthread_rwlock/enable_in_ci branch from eecc37a to 0a138f6 Compare August 20, 2019 15:28
@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 20, 2019

Squashed.

@jcarrano jcarrano added CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR and removed CI: needs squashing Commits in this PR need to be squashed; If set, CI systems will mark this PR as unmergable labels Aug 20, 2019
cladmi added 2 commits August 21, 2019 15:46
The test assumes that 'printf/puts' are non interruptible operations.
Use a mutex to guarantee it.

Without this, the automated test was failing in some configurations with
lines being cut by others.
HACK, the test currently fails in CI for `native` due to `utf-8` handling.
@cladmi cladmi force-pushed the pr/tests/pthread_rwlock/enable_in_ci branch from 0a138f6 to 9cd08d4 Compare August 21, 2019 13:47
@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 21, 2019

I rebased to fix the conflicts from #11680

@jcarrano jcarrano merged commit e7957e6 into RIOT-OS:master Aug 21, 2019
@cladmi
Copy link
Copy Markdown
Contributor Author

cladmi commented Aug 21, 2019

Thank you for the review.

@cladmi cladmi deleted the pr/tests/pthread_rwlock/enable_in_ci branch August 21, 2019 15:25
@kb2ma kb2ma added this to the Release 2019.10 milestone Sep 16, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Area: tests Area: tests and testing framework CI: disable test cache If set, CI will always run all tests regardless of whether they have been run successfully before CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR CI: run tests If set, CI server will run tests on hardware for the labeled PR

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants