Весь цикл занимает больше времени, чем сумма его итераций - PullRequest
Новая
       13

Весь цикл занимает больше времени, чем сумма его итераций

0 голосов
/ 04 октября 2018

мы столкнулись с особой проблемой при профилировании определенной части в нашем коде. 

auto timeSum = 0ul;
auto tOuterBeg = std::chrono::high_resolution_clock::now();
for (auto& camera : cameras) {
  auto tInnerBeg = std::chrono::high_resolution_clock::now();
  // read camera frame and process it
  auto tInnerEnd = std::chrono::high_resolution_clock::now();
  timeSum += std::chrono::duration_cast<std::chrono::milliseconds>(tInnerEnd - tInnerBeg).count();
}
auto tOuterEnd = std::chrono::high_resolution_clock::now();
auto outerDur = std::chrono::duration_cast<std::chrono::milliseconds>(tOuterEnd - tOuterBeg).count();
std::cout << "inner: " << timeSum << " outer: " << outerDur << "\n";

Внешняя длительность получается гораздо большим числом, разница составляет до 14 миллисекунд, что являетсямного, когда одно измерение составляет 27 миллисекунд, а другое - 41 миллисекунду.Код работает на процессоре ARM и кросс-компилируется с использованием оптимизированной (O3) сборки GCC 7.Мы постарались свести к минимуму количество потоков, используемых нашей программой, но не увидели никаких изменений, и у нас закончились идеи о том, что может быть причиной здесь.Любые идеи, указывающие на возможную причину, приветствуются.

РЕДАКТИРОВАТЬ: std :: high_resolution_clock должен иметь гораздо большую точность, чем миллисекунды.Кроме того, я попытался заменить цикл на блоки для каждой камеры следующим образом: 

auto timeSum = 0ul;
auto tOuterBeg = std::chrono::high_resolution_clock::now();
{
  auto tInnerBeg = std::chrono::high_resolution_clock::now();
  // read and process camera 1
  auto tInnerEnd = std::chrono::high_resolution_clock::now();
  timeSum += std::chrono::duration_cast<std::chrono::milliseconds>(tInnerEnd - tInnerBeg).count();
}
auto t1_ = std::chrono::high_resolution_clock::now();
{
  auto tInnerBeg = std::chrono::high_resolution_clock::now();
  // read and process camera 2
  auto tInnerEnd = std::chrono::high_resolution_clock::now();
  timeSum += std::chrono::duration_cast<std::chrono::milliseconds>(tInnerEnd - tInnerBeg).count();
}
auto t2_ = std::chrono::high_resolution_clock::now();
{
  auto tInnerBeg = std::chrono::high_resolution_clock::now();
  // read and process camera 3
  auto tInnerEnd = std::chrono::high_resolution_clock::now();
  timeSum += std::chrono::duration_cast<std::chrono::milliseconds>(tInnerEnd - tInnerBeg).count();
}
auto t3_ = std::chrono::high_resolution_clock::now();
{
  auto tInnerBeg = std::chrono::high_resolution_clock::now();
  // read and process camera 4
  auto tInnerEnd = std::chrono::high_resolution_clock::now();
  timeSum += std::chrono::duration_cast<std::chrono::milliseconds>(tInnerEnd - tInnerBeg).count();
}
auto tOuterEnd = std::chrono::high_resolution_clock::now();
auto outerDur = std::chrono::duration_cast<std::chrono::milliseconds>(tOuterEnd - tOuterBeg).count();
auto outsideBlockSum = (t1_ - tOuterBeg) + (t2_ - t1_) + (t3_ - t2_) + (tOuterEnd - t3_);

std::cout << "inner: " << timeSum << " outer: " << outerDur << " outside block parts sum: " << outsideBlockSum "\n";

Чтобы исключить любые погрешности часов - timeSum и outsideBlockSum равны, а timeSum на несколько миллисекунд ниже.

EDIT2: Как отметил @RobertAndrzejuk, деструкторы вызываются после добавления продолжительности внутри цикла.Это было немного сложнее, так как мы создавали std :: shared_ptr и передавали его поставщику данных, который затем распределяет его по программе, поэтому обычно удаление shared_ptr вызывается в потоке потребителя.Однако у трех из четырех камер не было подписчиков, и, как это было реализовано, средство удаления shared_ptr вызывалось в потоке обработки.

Ответы [ 2 ]

0 голосов
/ 04 октября 2018

Ваши функции синхронизации не включают время, затрачиваемое деструкторами.

Я бы создал класс, который в своем конструкторе "запускает часы".Затем в деструкторе он «останавливает часы» и добавляет длительность к общему значению длительности.

Примерно так: 

class TimeThis
{
    unsigned long& time_sum;

    const std::chrono::time_point< std::chrono::steady_clock > start;

public:
    TimeThis(unsigned long& time_sum)
          : time_sum(time_sum), start(std::chrono::high_resolution_clock::now())
    {}
    ~TimeThis()
    {
        const auto end = std::chrono::high_resolution_clock::now();
        time_sum +=
              std::chrono::duration_cast< std::chrono::milliseconds >(end - start).count();
    }
};

Затем в цикле, который вы выполняете, вы можете вызватьэто (первое, поэтому его деструктор называется последним - деструкторы вызываются в противоположном порядке от всех созданных объектов): 

for (auto& camera : cameras) {
    TimeThis t(timeSum);
  // read camera frame and process it
}

Другой способ - создать функцию, которая принимает лямбду и времявокруг выполнения лямбды.

Есть много способов сделать это.

0 голосов
/ 04 октября 2018

Вот краткий вариант вашего кода: 

#include <chrono>
#include <iostream>
int main()
{
    auto tOuterBeg = std::chrono::high_resolution_clock::now();
    auto timeSum = 0ul;

    for (int i = 0 ; i < 10000 ;++i) {
          auto tInnerBeg = std::chrono::high_resolution_clock::now();
          auto tInnerEnd = std::chrono::high_resolution_clock::now();
          timeSum += std::chrono::duration_cast<std::chrono::milliseconds>(tInnerEnd - tInnerBeg).count();
    }
    auto tOuterEnd = std::chrono::high_resolution_clock::now();
    auto outerDur = std::chrono::duration_cast<std::chrono::milliseconds>(tOuterEnd - tOuterBeg).count();
    std::cout << "inner: " << timeSum << " outer: " << outerDur << "\n";
}

На wandbox с GCC (8.2.0 с -O2) это печатает: 

inner: 0 outer: 26

Но эта огромная разницатолько потому, что миллисекунды слишком грубы для синхронизации цикла.С chrono::microseconds дела обстоят лучше: 

inner: 10462 outer: 23960

Это все еще не хорошо, но все же намного лучше, чем раньше.Далее, факт, что в каждой итерации есть два вызова high_resolution_clock::now().timeSum раз только один из вызовов now(), но outerDur учитывает оба.Это объясняет, почему outer отображает примерно вдвое больше inner.

Если вы измените цикл на вызов high_resolution_clock::now() только один раз за итерацию, тогда разница между outerDur и timeSum будетбыть намного меньше: 

auto tInnerBeg = std::chrono::high_resolution_clock::now();
for (int i = 0 ; i < 10000 ;++i) {
      auto tInnerEnd = std::chrono::high_resolution_clock::now();
      timeSum += std::chrono::duration_cast<std::chrono::microseconds>(tInnerEnd - tInnerBeg).count();
      tInnerBeg = tInnerEnd;
}

Результат этого намного ближе к тому, что вы ожидаете: 

inner: 10817 outer: 12912

Разницу можно еще больше устранить, перейдя на наносекунды.Кажется, что округление микросекунд приводит к слишком большим ошибкам: 

inner: 13612956 outer: 13614153

Небольшая разница обусловлена ​​стоимостью duration_cast и самой петлей.

В целом, кажется, что намашина wandbox, один звонок на std::chrono::high_resolution_clock::now() занимает 1,361 мкс.Примите это во внимание.

РЕДАКТИРОВАТЬ

Видя редактирование вопроса, я должен согласиться с Робертом Анджеюком, что для небольшого числа итераций, равного 4, проблема, вероятно, связана с временем, проведенным в деструкторах,Для подсчета в деструкторах вы можете собрать время после запуска деструкторов, поместив код в отдельный и внутренний блок {}: 

auto tInnerBeg = std::chrono::high_resolution_clock::now();
for (int i = 0 ; i < 10000 ;++i) {
      {
         ////////////////////////
         // the timed code goes here
         //////////////////////////
      }
      auto tInnerEnd = std::chrono::high_resolution_clock::now();
      timeSum += std::chrono::duration_cast<std::chrono::microseconds>(tInnerEnd - tInnerBeg).count();
      tInnerBeg = tInnerEnd;
}
...