Порядок вывода в консоль замедляет работу многопоточной программы

При компиляции следующего кода

#include <iostream>
#include <vector>
#include <thread>
#include <chrono>
#include <mutex>

std::mutex cout_mut;

void task()
{
    for(int i=0; i<10; i++)
    {
        double d=0.0;
        for(size_t cnt=0; cnt<200000000; cnt++) d += 1.23456;

        std::lock_guard<std::mutex> lg(cout_mut);
        std::cout << d << "(Help)" << std::endl;
        //        std::cout << "(Help)" << d << std::endl;
    }
}

int main()
{
    std::vector<std::thread> all_t(std::thread::hardware_concurrency());

    auto t_begin = std::chrono::high_resolution_clock::now();

    for(auto& t : all_t) t = std::thread{task};
    for(auto& t : all_t) t.join();

    auto t_end = std::chrono::high_resolution_clock::now();

    std::cout << "Took : " << (t_end - t_begin).count() << std::endl;
}

В MinGW 4.8.1 выполнение на моем компьютере занимает примерно 2,5 секунды. Примерно столько времени требуется для однопоточного выполнения функции task.

Однако, когда я раскомментирую строку в середине и, следовательно, закомментирую строку перед (то есть, когда я заменю порядок, в котором d и "(Help)" записываются на std::cout), все это занимает теперь 8-9 секунд.

Каково объяснение?

Я снова проверил и обнаружил, что у меня проблема только с MinGW-сборкой x32-4.8.1-win32-dwarf-rev3, но не с MinGW-сборкой x64-4.8.1-posix-seh-rev3. У меня 64-битная машина. С 64-битным компилятором обе версии занимают три секунды. Однако при использовании 32-разрядного компилятора проблема остается (и не из-за путаницы версии выпуска/отладки).


concurrency c++11 mutex stdthread
person Toby Brull    schedule 04.08.2013    source источник
comment
Могло ли так случиться, что вы получили быстрое время от сборки выпуска и медленное время от сборки отладки? Я не вижу существенной разницы при свапе, с gcc 4.7.2/4.8.1, clang 3.2/3.3 (все Linux). Но для выпускных сборок я получаю около 2 секунд, а для отладки - около 8. Заметно похоже на соотношение, которое вы видите (в Windows, на какой-то другой машине).   -  person Mike Kinghan    schedule 05.08.2013
comment
Нет, это не проблема отладки/релиза; пожалуйста, смотрите мое редактирование выше.   -  person Toby Brull    schedule 05.08.2013
comment
Кажется, разница x87 fpu для 32-битной и SSE2 для 64-битной. 32-разрядный компилятор может генерировать (медленные) коды инструкций x87 для double операций.   -  person yohjp    schedule 12.08.2013
comment
Похоже, gcc 4.8.1 производит совсем другую сборку для внутреннего цикла. В одном случае это просто добавление константы в xmm0. В другом случае промежуточный результат накапливается в стеке, создавая две дополнительные инструкции movsd в дополнение к addd.   -  person Come Raczy    schedule 12.08.2013

Ответы (1)


arrow_upward
1
arrow_downward

Это не имеет ничего общего с многопоточностью. Это проблема оптимизации цикла. Я изменил исходный код, чтобы получить что-то минималистичное, демонстрирующее проблему:

#include <iostream>
#include <chrono>
#include <mutex>

int main()
{
    auto t_begin = std::chrono::high_resolution_clock::now();
    for(int i=0; i<2; i++)
    {
        double d=0.0;
        for(int j=0; j<100000; j++) d += 1.23456;
        std::mutex mutex;
        std::lock_guard<std::mutex> lock(mutex);
#ifdef SLOW
        std::cout << 'a' << d << std::endl;
#else
        std::cout << d << 'a' << std::endl;
#endif
    }
    auto t_end = std::chrono::high_resolution_clock::now();
    std::cout << "Took : " << (static_cast<double>((t_end - t_begin).count())/1000.0) << std::endl;
}

При компиляции и выполнении и с:

g++ -std=c++11 -DSLOW -o slow -O3 b.cpp -lpthread ; g++ -std=c++11 -o fast -O3 b.cpp -lpthread ; ./slow ; ./fast

Результат:

a123456
a123456
Took : 931
123456a
123456a
Took : 373

Большая часть разницы во времени объясняется ассемблерным кодом, сгенерированным для внутреннего цикла: быстрый регистр накапливается непосредственно в xmm0, а медленный регистр накапливается в xmm1, что приводит к двум дополнительным инструкциям movsd.

Теперь при компиляции с опцией '-ftree-loop-linear':

g++ -std=c++11 -ftree-loop-linear -DSLOW -o slow -O3 b.cpp -lpthread ; g++ -std=c++11 -ftree-loop-linear -o fast -O3 b.cpp -lpthread ; ./slow ; ./fast

Вывод становится:

a123456
a123456
Took : 340
123456a
123456a
Took : 346
person Come Raczy    schedule 13.08.2013