Helgrind nie przepada za Google Test

Helgrind nie przepada za Google Test. Za Boost Test również. I za Catch2 też. Właściwie to nie przepada za każdą biblioteką do testów automatycznych wykonującą wiele przypadków testowych w ramach pojedynczego wywołania programu z testami.

Helgrind to narzędzie w ramach oprogramowania Valgrind służące do wykrywania problemów związanych z synchronizacją wątków. Helgrind potrafi między innymi wykrywać:

niepoprawne użycie API biblioteki pthreads,
potencjalne zakleszczenia związane z kolejnością akwizycji lock-ów,
wyścigi w dostępie do danych wynikające z braku zastosowania mechanizmów synchronizacji.

Problem z Helgind

Helgrind podczas działania wykrywa użycie mechanizmów synchronizacji i identyfikuje je po adresie obiektów reprezentujących te mechanizmy. Niestety helgrind nie uwzględnia, kiedy pamięć takiego obiektu jest zwalniana, przez co prowadzi to do fałszywie pozytywnych ostrzeżeń.

Problem ten można wywołać poprzez uruchomienie następującego kodu:

#include "gtest/gtest.h"

#include <mutex>
#include <memory>
#include <iostream>


class SyncDataA {
    std::mutex mutex1;
    std::mutex mutex2;
public:
    void trylock12() {
        std::scoped_lock lock1(mutex1);
        std::scoped_lock lock2(mutex2);
    }
};

class SyncDataB {
    std::mutex mutex1b;
    std::mutex mutex2b;
public:
    void trylock21() {
        std::scoped_lock lock2(mutex2b);
        std::scoped_lock lock1(mutex1b);
    }
};

/// =====================================

TEST(HelgrindSuite, test_a) {
    SyncDataA data;
    data.trylock12();
}

TEST(HelgrindSuite, test_b) {
    SyncDataB data;
    data.trylock21();
}

Powyższy kod zawiera dwie klasy zawierające po dwa obiekty typu std::mutex oraz dwa przypadki testowe. Klasy te nie są w jakikolwiek sposób ze sobą powiązane. Test test_a zawiera wywołanie metody trylock12() klasy SyncDataA, natomiast test test_b zawiera wywołanie metody trylock21() klasy SyncDataB.

Uruchomienie testów pod kontrolą valgrind spowoduje zgłoszenie błędu lock order violation:

==286192== ---Thread-Announcement------------------------------------------
==286192== 
==286192== Thread #1 is the program's root thread
==286192== 
==286192== ----------------------------------------------------------------
==286192== 
==286192== Thread #1: lock order "0x1FFEFFF850 before 0x1FFEFFF878" violated
==286192== 
==286192== Observed (incorrect) order is: acquisition of lock at 0x1FFEFFF878
==286192==    at 0x48512DC: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so)
==286192==    by 0x110E86: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:749)
==286192==    by 0x110FC9: std::mutex::lock() (std_mutex.h:113)
==286192==    by 0x111383: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) (mutex:779)
==286192==    by 0x1110E6: SyncDataB::trylock21() (helgrind_test.cpp:23)
==286192==    by 0x110B02: HelgrindSuite_test_b_Test::TestBody() (helgrind_test.cpp:37)
==286192==    by 0x141791: void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2402)
==286192==    by 0x13A322: void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2438)
==286192==    by 0x11A051: testing::Test::Run() (gtest.cc:2474)
==286192==    by 0x11AABB: testing::TestInfo::Run() (gtest.cc:2656)
==286192==    by 0x11B1D8: testing::TestCase::Run() (gtest.cc:2774)
==286192==    by 0x122B94: testing::internal::UnitTestImpl::RunAllTests() (gtest.cc:4649)
==286192== 
==286192==  followed by a later acquisition of lock at 0x1FFEFFF850
==286192==    at 0x48512DC: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so)
==286192==    by 0x110E86: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:749)
==286192==    by 0x110FC9: std::mutex::lock() (std_mutex.h:113)
==286192==    by 0x111383: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) (mutex:779)
==286192==    by 0x1110F9: SyncDataB::trylock21() (helgrind_test.cpp:24)
==286192==    by 0x110B02: HelgrindSuite_test_b_Test::TestBody() (helgrind_test.cpp:37)
==286192==    by 0x141791: void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2402)
==286192==    by 0x13A322: void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2438)
==286192==    by 0x11A051: testing::Test::Run() (gtest.cc:2474)
==286192==    by 0x11AABB: testing::TestInfo::Run() (gtest.cc:2656)
==286192==    by 0x11B1D8: testing::TestCase::Run() (gtest.cc:2774)
==286192==    by 0x122B94: testing::internal::UnitTestImpl::RunAllTests() (gtest.cc:4649)
==286192== 
==286192== Required order was established by acquisition of lock at 0x1FFEFFF850
==286192==    at 0x48512DC: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so)
==286192==    by 0x110E86: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:749)
==286192==    by 0x110FC9: std::mutex::lock() (std_mutex.h:113)
==286192==    by 0x111383: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) (mutex:779)
==286192==    by 0x111032: SyncDataA::trylock12() (helgrind_test.cpp:13)
==286192==    by 0x110AA8: HelgrindSuite_test_a_Test::TestBody() (helgrind_test.cpp:32)
==286192==    by 0x141791: void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2402)
==286192==    by 0x13A322: void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2438)
==286192==    by 0x11A051: testing::Test::Run() (gtest.cc:2474)
==286192==    by 0x11AABB: testing::TestInfo::Run() (gtest.cc:2656)
==286192==    by 0x11B1D8: testing::TestCase::Run() (gtest.cc:2774)
==286192==    by 0x122B94: testing::internal::UnitTestImpl::RunAllTests() (gtest.cc:4649)
==286192== 
==286192==  followed by a later acquisition of lock at 0x1FFEFFF878
==286192==    at 0x48512DC: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so)
==286192==    by 0x110E86: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:749)
==286192==    by 0x110FC9: std::mutex::lock() (std_mutex.h:113)
==286192==    by 0x111383: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) (mutex:779)
==286192==    by 0x111049: SyncDataA::trylock12() (helgrind_test.cpp:14)
==286192==    by 0x110AA8: HelgrindSuite_test_a_Test::TestBody() (helgrind_test.cpp:32)
==286192==    by 0x141791: void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2402)
==286192==    by 0x13A322: void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2438)
==286192==    by 0x11A051: testing::Test::Run() (gtest.cc:2474)
==286192==    by 0x11AABB: testing::TestInfo::Run() (gtest.cc:2656)
==286192==    by 0x11B1D8: testing::TestCase::Run() (gtest.cc:2774)
==286192==    by 0x122B94: testing::internal::UnitTestImpl::RunAllTests() (gtest.cc:4649)
==286192== 
==286192==  Lock at 0x1FFEFFF850 was first observed
==286192==    at 0x48512DC: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so)
==286192==    by 0x110E86: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:749)
==286192==    by 0x110FC9: std::mutex::lock() (std_mutex.h:113)
==286192==    by 0x111383: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) (mutex:779)
==286192==    by 0x111032: SyncDataA::trylock12() (helgrind_test.cpp:13)
==286192==    by 0x110AA8: HelgrindSuite_test_a_Test::TestBody() (helgrind_test.cpp:32)
==286192==    by 0x141791: void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2402)
==286192==    by 0x13A322: void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2438)
==286192==    by 0x11A051: testing::Test::Run() (gtest.cc:2474)
==286192==    by 0x11AABB: testing::TestInfo::Run() (gtest.cc:2656)
==286192==    by 0x11B1D8: testing::TestCase::Run() (gtest.cc:2774)
==286192==    by 0x122B94: testing::internal::UnitTestImpl::RunAllTests() (gtest.cc:4649)
==286192==  Address 0x1ffefff850 is on thread #1's stack
==286192==  in frame #5, created by HelgrindSuite_test_b_Test::TestBody() (helgrind_test.cpp:35)
==286192== 
==286192==  Lock at 0x1FFEFFF878 was first observed
==286192==    at 0x48512DC: ??? (in /usr/libexec/valgrind/vgpreload_helgrind-amd64-linux.so)
==286192==    by 0x110E86: __gthread_mutex_lock(pthread_mutex_t*) (gthr-default.h:749)
==286192==    by 0x110FC9: std::mutex::lock() (std_mutex.h:113)
==286192==    by 0x111383: std::scoped_lock<std::mutex>::scoped_lock(std::mutex&) (mutex:779)
==286192==    by 0x111049: SyncDataA::trylock12() (helgrind_test.cpp:14)
==286192==    by 0x110AA8: HelgrindSuite_test_a_Test::TestBody() (helgrind_test.cpp:32)
==286192==    by 0x141791: void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2402)
==286192==    by 0x13A322: void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) (gtest.cc:2438)
==286192==    by 0x11A051: testing::Test::Run() (gtest.cc:2474)
==286192==    by 0x11AABB: testing::TestInfo::Run() (gtest.cc:2656)
==286192==    by 0x11B1D8: testing::TestCase::Run() (gtest.cc:2774)
==286192==    by 0x122B94: testing::internal::UnitTestImpl::RunAllTests() (gtest.cc:4649)
==286192==  Address 0x1ffefff878 is on thread #1's stack
==286192==  in frame #5, created by HelgrindSuite_test_b_Test::TestBody() (helgrind_test.cpp:35)
==286192== 
==286192==

Kod został skompilowany i uruchomiony z wykorzystaniem:

gcc 13.3.0
googletest 1.7.0
valgrind 3.22.0
Ubuntu 24.04.2 LTS

Przyczyna

Klasy SyncDataA oraz SyncDataB mają identyczny układ pamięci: zawierają po dwa pola służące do synchronizacji. W metodzie SyncDataA::trylock12() pola te wywołane są w kolejności: pierwszy mutex, następnie drugi mutex. W drugiej klasie wywołanie mutex-ów następuje w odwrotnej kolejności. Musi wystąpić jeszcze jeden warunek konieczny: każdy obiekt tych klas jest powoływany na stosie w dokładnie tym samym adresie pamięci.

Analiza logiczna kodu wprost wskazuje, że problem zakleszczenia nie ma możliwości wystąpienia, ponieważ każda z klas używa innych instancji mutex-ów. Valgrind jednak, ze względu na wykorzystanie tych samych adresów komórek pamięci, wskazuje na potencjalne zakleszczenie (lock order violation).

Co robić, jak żyć?

Zdawać by się mogło, że prawdopodobieństwo zaistnienia wszystkich wymaganych warunków jest skrajnie niskie, jednak tak nie jest. Autor doświadczył tego problemu na niewielkiej bibliotece wykorzystującej w kodzie kilka(naście) mutex-ów. Ponadto prawdopodobieństwo wystąpienia problemu wzrasta wraz z przyrostem liczby przypadków testowych.

Skutecznym rozwiązaniem jest uruchamianie każdego przypadku testowego w osobnym procesie. W tym celu Google Test wyposażony jest w dwa parametry: --gtest_list_tests oraz --gtest_filter, które można wykorzystać w skrypcie:

#!/bin/bash

##
## Script wrapping up gtest executable. Allows to run helgrind for each test case 
## separately preventing "lock order violated" false-positive.
##

set -eu

SCRIPT_DIR=$(dirname "$(readlink -f "$0")")


TESTS_EXECUTABLE="${SCRIPT_DIR}/helgrind_tests"

HELGRIND_CALL="valgrind --exit-on-first-error=yes --error-exitcode=1 --tool=helgrind"


# ================================================

usage() {
    echo "gtest runner"
    echo
    echo "syntax: $(basename $0) [-h|--help] [<gtest-arguments>] [--hel|--helgrind [<helgrind-arguments>]]"
    echo
    echo "options:"
    echo "  -h|--help            - this information"
    echo "  --hel|--helgrind     - run tests with helgrind"
    echo "  <gtest-arguments>    - arguments passed to tests executable"
    echo "  <helgrind-arguments> - arguments passed to helgrind executable (if enabled)"
    echo
}

# ================================================


GTEST_ARGS=()
GTEST_FILTER=""

HELGRIND_ARGS=()
HELGRIND_ENABLED=0


while :; do
    if [ -z "${1+x}" ]; then
        ## end of arguments (prevents unbound argument error)
        break
    fi

    case "$1" in
      -h|--help)            usage 
                            exit 0;;

      --hel|--helgrind)     HELGRIND_ENABLED=1
                            shift ;;

      --gtest_filter=*)     if [[ ${HELGRIND_ENABLED} -eq 0 ]]; then
                                GTEST_FILTER="${1#*=}"
                            fi
                            ## fallthrough
                            ;&

      *)    if [[ ${HELGRIND_ENABLED} -eq 0 ]]; then
                GTEST_ARGS+=("$1")
            else
                HELGRIND_ARGS+=("$1")
            fi
            shift ;;
    esac
done


if [[ ${HELGRIND_ENABLED} -eq 0 ]]; then
    ## run normal tests
    "$TESTS_EXECUTABLE" ${GTEST_ARGS[@]}
    echo "completed"
    exit 0
fi


## running tests with helgrind
TEST_CASES=$("${TESTS_EXECUTABLE}" --gtest_list_tests | awk '/\./{ SUITE=$1 }  /  / { print SUITE $1 }')

if [[ "${GTEST_FILTER}" == "" ]]; then
    ## match all test cases
    GTEST_FILTER="*"
fi

for test_case in ${TEST_CASES}; do
    ## matching test cases with filter
    if [[ ${test_case} == ${GTEST_FILTER} ]]; then
        echo "====== running test case: ${test_case} ======"
        ${HELGRIND_CALL} ${HELGRIND_ARGS[@]} "${TESTS_EXECUTABLE}" --gtest_filter=${test_case} ${GTEST_ARGS[@]}

        echo
    fi
done

echo "completed"

W skrypcie zdefiniowana jest zmienna TESTS_EXECUTABLE, która powinna zawierać ścieżkę do pliku wykonywalnego z testami. W łatwy sposób, przykładowo przy pomocy CMake, można wygenerować taki skrypt dla każdego programu z testami.

Podsumowanie

Helgrind jest nieocenionym narzędziem w walce z trudnymi do zdiagnozowania błędami związanymi z synchronizacją wątków. Niestety trzeba być świadomym ograniczeń związanych z tym narzędziem.

Twój zespół potrzebuje wsparcia w analizie kodu?

Napisz lub zadzwoń

SoftFlow

Helgrind nie przepada za Google Test

Problem z Helgind

Przyczyna

Co robić, jak żyć?

Podsumowanie

Leave a Reply Cancel reply