Skip to content

Logger: move self%buffer and seld%len_buffer to local variables #253

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

Merged
merged 4 commits into from
Nov 28, 2020

Conversation

jvdp1
Copy link
Member

@jvdp1 jvdp1 commented Nov 26, 2020

I was testing a multi-threading (OpenMP) program with global_logger inside an OpenMP loop. I got a segfault because a thread tried to allocate seld % buffer while it was already allocated by another thread.
As a solution, I moved the variables self % buffer and self % len_buffer into the subroutines log_messge and log_text_error. I believe that this solution has been already proposed in another discussion (I can't retrieve it).

Note that this modification solves the problem of segfault, but it does not make the logger thread-safe. AFAIK, to be thread-safe, the logger (or the write statement inside the logger) should be in an OpenMP critical section.

@jvdp1
Copy link
Member Author

jvdp1 commented Nov 26, 2020

@wclodius2 do you see any possible problems I overlook with these modifications?

@wclodius2
Copy link
Contributor

Its a lot mom changes, but as they mostly involve removing self % they look straightforward. I don't see any problems. In the code not shown, any problems would probably show up with implicit none so I have strong confidence the code is correct. I suspect it is more robust than my code. Did you check the test cases?

Copy link
Member

@awvwgk awvwgk 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 not really familiar with the API, but looking over this change rises the question why the logger should be mutable (intent(inout)) when logging in the first place? I don't see a good reason to allow a procedure to have a side effect by modifying the logger when writing the log.

Making the logger immutable (intent(in)) seems to work together with this change as expected:

diff --git a/src/stdlib_logger.f90 b/src/stdlib_logger.f90
index 6fd1188..c503645 100644
--- a/src/stdlib_logger.f90
+++ b/src/stdlib_logger.f90
@@ -521,7 +521,7 @@ contains
 !! Writes the STRING to UNIT ensuring that the number of characters
 !! does not exceed MAX_WIDTH and that the lines after the first
 !! one are indented four characters.
-        class(logger_type), intent(inout)          :: self
+        class(logger_type), intent(in)             :: self
         integer, intent(out)                       :: len_buffer
         character(*), intent(in)                   :: string
         character(*), intent(in)                   :: col_indent
@@ -799,7 +799,7 @@ contains
 !!     end module example_mod
 !!
 
-        class(logger_type), intent(inout)       :: self
+        class(logger_type), intent(in)          :: self
 !! The logger to be used in logging the message
         character(len=*), intent(in)            :: message
 !! A string to be written to log_unit
@@ -888,7 +888,7 @@ contains
 !!     end module example_mod
 !!
 
-        class(logger_type), intent(inout)       :: self
+        class(logger_type), intent(in)          :: self
 !! The logger used to send the message
         character(len=*), intent(in)            :: message
 !! A string to be written to log_unit
@@ -941,7 +941,7 @@ contains
 !!      ...
 !!    end program example
 
-        class(logger_type), intent(inout)       :: self
+        class(logger_type), intent(in)          :: self
 !! The logger variable to receivee the message
         character(len=*), intent(in)            :: message
 !! A string to be written to LOG_UNIT
@@ -1027,7 +1027,7 @@ contains
 !!    end module example_mod
 !!
 
-        class(logger_type), intent(inout)       :: self
+        class(logger_type), intent(in)          :: self
 !! The logger variable to receive the message
         character(len=*), intent(in)            :: message
 !! A string to be written to log_unit
@@ -1153,7 +1153,7 @@ contains
 !!      ...
 !!    end program example
 !!
-        class(logger_type), intent(inout)     :: self
+        class(logger_type), intent(in)        :: self
 !! The logger variable to receive the message
         character(*), intent(in)              :: line
 !! The line of text in which the error was found.
@@ -1365,7 +1365,7 @@ contains
 !!       ...
 !!     end module example_mod
 !!
-        class(logger_type), intent(inout)       :: self
+        class(logger_type), intent(in)          :: self
 !! The logger to which the message is written
         character(len=*), intent(in)            :: message
 !! A string to be written to LOG_UNIT

@wclodius2
Copy link
Contributor

There are some points of style in the code. A lot of instances of self with intent(inout) should now be intent(in), i.e., in format_output_string and I believe all log_.... In format_output_string the type declaration statements for the dummy arguments should be in the order of the argument list. The document stdlib_logger.md should be revised to eliminate the references to buffer and len_buffer in the discussion of the derived type and the intents for self in the appropriate procedures should be revised.

@awvwgk
Copy link
Member

awvwgk commented Nov 26, 2020

I was testing a multi-threading (OpenMP) program with global_logger inside an OpenMP loop. I got a segfault because a thread tried to allocate seld % buffer while it was already allocated by another thread.

This is kind of a pity with OpenMP, a derived type with allocatable members seems to get memcopied if it is set to firstprivate, resulting in private copies for each thread potentially pointing to the same the location. The only safe way I found so far working with a mutable derived type was to have it shared and read-only, while deep-copying it manually to a private instance in the OpenMP region, which is kind of a waste.

OpenACC has a mechanism to copyin components of derived types explicitly, but I'm not aware of a similar mechanism in OpenMP.

Note that this modification solves the problem of segfault, but it does not make the logger thread-safe. AFAIK, to be thread-safe, the logger (or the write statement inside the logger) should be in an OpenMP critical section.

The OpenMP critical should probably be provided on the user side of the API to ensure that two independent loggers don't block each other. If stdlib wants to handle the thread-safety itself, than it probably has to create an OpenMP mutex for each unit connected to the logger, but I'm not sure if this can be done with a normal OpenMP critical region (have to read the specs again).

Copy link
Member

@14NGiestas 14NGiestas left a comment

Choose a reason for hiding this comment

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

It looks ok and CI tests passed (mostly, despite the issue with MacOS).

Co-authored-by: Sebastian Ehlert <28669218+awvwgk@users.noreply.github.com>
@jvdp1
Copy link
Member Author

jvdp1 commented Nov 27, 2020

Thank you for your reviews. Indeed, many intent(inout) should be modified and the specs should be adapted as well. I will do it.

Now done in:
commit
and
commit

Copy link
Member

@awvwgk awvwgk left a comment

Choose a reason for hiding this comment

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

Thanks, looks good to me now.

@jvdp1
Copy link
Member Author

jvdp1 commented Nov 27, 2020

@awvwgk Thank you for your comments.

This is kind of a pity with OpenMP, a derived type with allocatable members seems to get memcopied if it is set to firstprivate, resulting in private copies for each thread potentially pointing to the same the location. The only safe way I found so far working with a mutable derived type was to have it shared and read-only, while deep-copying it manually to a private instance in the OpenMP region, which is kind of a waste.

I usually avoid to use (first/last)private for large arrays or derived types (too often bitten with stack memory issues, and issues similar to the one you mentioned). I prefer deep-copying and explicit allocation of copies.

With the proposed changes (and the logger being unmutable in the OpenMP parallel region), the following OpenMP code should work without issues:

   use stdlib_logger, only: logger_type, global => global_logger, success
    !$ use omp_lib
    implicit none
    integer :: i, ithread, nthreads, stat
    character(len = 30) :: cdummy, cdummy1
    type(logger_type), allocatable :: logger(:)

    call global % add_log_file( 'log_file_omp.txt')

    nthreads = 1
    !$omp parallel
    !$ nthreads = omp_get_num_threads()
    !$omp end parallel

    write(cdummy, '(i0)') nthreads

    ithread = 1
    cdummy = 'master'
    !$omp parallel default(none) &
    !$omp shared(global) &
    !$omp private(i, ithread, cdummy, cdummy1)
    !$omp do
    do i = 1, 100  
        !$ ithread = omp_get_thread_num()+1
        !$ write(cdummy, '(i0)') ithread
        write(cdummy1, '(i0)') i
        !$omp critical
        call global % log_message('Thread : ' // trim(cdummy) //&
             ' | i = ' // trim(cdummy1))
        !$omp end critical
    end do
    !$omp end do
    !$omp end parallel
end program

The user could omit the OpenMP critical section but this could lead to overwritting.

Question: should such an example be provide in the specs?

The OpenMP critical should probably be provided on the user side of the API ...

I agree with this statement. My main reason is that there are several ways for multi-thread programming. Controlling it outside stdlib does not enforce the user to use a specific approach to be thread-safe.

... to ensure that two independent loggers don't blog each other. If stdlib wants to handle the thread-safety itself, than it probably has to create an OpenMP mutex for each unit connected to the logger, but I'm not sure if this can be done with a normal OpenMp critical region (have to read the specs again).

Named OpenMP critical section could be used (e.g. 1 named critical section per unit connected to the logger). But, as stated earlier, I don't think it should be the way to go.

@awvwgk
Copy link
Member

awvwgk commented Nov 27, 2020

Named OpenMP critical section could be used (e.g. 1 named critical section per unit connected to the logger). But, as stated earlier, I don't think it should be the way to go.

OpenMP critical (even with named sections) will not work correctly, maybe the hint-expression introduced in OpenMP 4.5 could solve this issue, but I have not tried them yet (some compiler vendors only support OpenMP 3.x yet). You would have to go for managing an array of locks to make this possible.

@jvdp1
Copy link
Member Author

jvdp1 commented Nov 27, 2020

Named OpenMP critical section could be used (e.g. 1 named critical section per unit connected to the logger). But, as stated earlier, I don't think it should be the way to go.

OpenMP critical (even with named sections) will not work correctly, maybe the hint-expression introduced in OpenMP 4.5 could solve this issue, but I have not tried them yet (some compiler vendors only support OpenMP 3.x yet). You would have to go for managing an array of locks to make this possible.

Indeed, you are right. Thank you for your comment.

@jvdp1
Copy link
Member Author

jvdp1 commented Nov 28, 2020

With 4 reviewers agreeing with the changes, I will merge this PR. Thank you all for your reviews and comments.

@jvdp1 jvdp1 merged commit e54f92a into fortran-lang:master Nov 28, 2020
@jvdp1 jvdp1 deleted the test_logger branch November 28, 2020 12:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants