Доброе время суток!

Недавно я обнаружил абсолютно загадочное для меня поведение в даже самых простых программах на Haskell. Суть явления такова: есть программа, что подключается к некому серверу, тащит оттуда текст строчка за строчкой, каждую строчку "обрабатывает" и скидывает на стандартный вывод время "обработки". Так вот... Если "сервер" шлет эти строчки без задержки, то программа работает очень шустро. Но как только задержка между сообщениями возникает (даже если это порядка миллисекунды), то программа начинает заметно тормозить.

Для чистоты эксперимента я гарантирую, что обработка выполнится, путем if блока с проверкой длины строки, и не вывожу результаты на stdout пока сервер не прикроет связь.

Потрясающе, но несмотря на кажущуюся изолированность кода, проводящего "обработку" очередной строки (в случае примера — просто 10 раз делается reverse), время выполнения отличается очень сильно. Я построил гистограммы и кажется что это самое время выполнения как бы умножилось на некоторый коэффициент. Причем он не зависит от интервалов времени между сообщениями, важно только то, равен этот интервал нулю или нет. И для случаев с 0 миллисекунд и 10 миллисекунд медианы получаются 21 и 37 микросекунд соответственно.

Пока что кажется что быть может планировщик задач как-то странно работает и если поток блокируется в попытке прочитать что-то из сокета — поток (или даже весь процесс) понижается в приоритете. Но даже это кажется неадекватным объяснением, т.к. вряд ли планировщик может так "мягко" притормозить фрагмент кода, что
выполняется несколько десятков микросекунд.

А как Вы думаете, что это может быть за штука?

--
P.S. Еще гонял эту штуку под профайлером. Толковых результатов получить не удалось. В случае с ненулевым интервалом времени между получаемыми строчками почти все время уходит в модуль MAIN, а все остальное — сплошные нули.

--

Ну а сама программа вот тут:

{-# LANGUAGE BangPatterns #-}

module Main where

import qualified Data.ByteString.Char8 as B
import System.Time
import System.IO
import Control.Exception hiding (catch)
import Control.Monad
import Data.Maybe
import Network
import Network.Socket

main = do
  putStrLn "total"
  s <- connectTo "localhost" $ PortNumber 4123
  hSetBuffering s $ LineBuffering
  hSetBuffering stdout $ LineBuffering
  pts <- collectWhileAvailable $ mProcessNextLine s -- process the incoming lines and collect the results
  hClose s
  forM_ pts $ \pt -> putStrLn $ show pt -- show the result

collectWhileAvailable :: IO (Maybe a) -> IO [a]
collectWhileAvailable mnext = do
  mvalue <- mnext
  case mvalue of
    Just value -> do
      rest <- collectWhileAvailable mnext
      return (value:rest)
    Nothing -> return []

mProcessNextLine s = (liftM Just $ processNextLine s) `catch` \e -> return Nothing

-- reads a line of text from socket, reverses it several times
-- (just to spend some time, proportionally to the size of the line),
-- calculates the time spent and returns it
processNextLine :: Handle -> IO Int
processNextLine s = do
  line <- B.hGetLine s
  startT <- getClockTime -- start of "processing"
  let line' = process line
  if 0 == B.length line' -- this is just to force the evaluation of line'
    then return 0
    else do
      endT <- getClockTime -- end of processing
      let processingTime = diffClockTimes endT startT
      let pt = (fromIntegral ((tdPicosec processingTime) `div` 1000000)) +
                (fromIntegral ((tdSec processingTime) * 1000000))
      return $! pt -- returning the time spent for "processing" in microseconds


process line = process' line 10
  where
    process' !line !n = if n == 0 then line else process' (B.reverse line) (n-1)

Здравствуйте, Rtveliashvili Denys, Вы писали:

RD>Доброе время суток!

RD>Пока что кажется что быть может планировщик задач как-то странно работает и если поток блокируется в попытке прочитать что-то из сокета — поток (или даже весь процесс) понижается в приоритете. Но даже это кажется неадекватным объяснением, т.к. вряд ли планировщик может так "мягко" притормозить фрагмент кода, что
RD>выполняется несколько десятков микросекунд.
RD>А как Вы думаете, что это может быть за штука?

RD>--
RD>P.S. Еще гонял эту штуку под профайлером. Толковых результатов получить не удалось. В случае с ненулевым интервалом времени между получаемыми строчками почти все время уходит в модуль MAIN, а все остальное — сплошные нули.

Вполне возможно, это внутренний планировщик Хаскеля.

Здравствуйте, Rtveliashvili Denys, Вы писали:

RD>Недавно я обнаружил абсолютно загадочное для меня поведение в даже самых простых программах на Haskell. Суть явления такова: есть программа, что подключается к некому серверу, тащит оттуда текст строчка за строчкой, каждую строчку "обрабатывает" и скидывает на стандартный вывод время "обработки". Так вот... Если "сервер" шлет эти строчки без задержки, то программа работает очень шустро. Но как только задержка между сообщениями возникает (даже если это порядка миллисекунды), то программа начинает заметно тормозить.

варианты — данные вытесняются из кеша/озу, тред вытесняется с процессора (насколько я помню у виндов шедулинг был порциями по 20 мс минимум), программа начинает auto-gc (+RTS -q, кажись)

окружение-то какое? ездействующая юзерская машина или сервер за $5/month?

Здравствуйте, Rtveliashvili Denys, Вы писали:

RD>Потрясающе, но несмотря на кажущуюся изолированность кода, проводящего "обработку" очередной строки (в случае примера — просто 10 раз делается reverse), время выполнения отличается очень сильно. Я построил гистограммы и кажется что это самое время выполнения как бы умножилось на некоторый коэффициент. Причем он не зависит от интервалов времени между сообщениями, важно только то, равен этот интервал нулю или нет. И для случаев с 0 миллисекунд и 10 миллисекунд медианы получаются 21 и 37 микросекунд соответственно.

строим график функции по двум точкам

RD>>Потрясающе, но несмотря на кажущуюся изолированность кода, проводящего "обработку" очередной строки (в случае примера — просто 10 раз делается reverse), время выполнения отличается очень сильно. Я построил гистограммы и кажется что это самое время выполнения как бы умножилось на некоторый коэффициент. Причем он не зависит от интервалов времени между сообщениями, важно только то, равен этот интервал нулю или нет. И для случаев с 0 миллисекунд и 10 миллисекунд медианы получаются 21 и 37 микросекунд соответственно.

BZ>строим график функции по двум точкам

И что смешного? Точек не две, я проверял на разных интервалах и получается вот такое: m(0 ms) = 21, m(n ms) = 37 где n >= 1.

Кстати, в этом конкретном примере торможение получается грубо в 1.5 раза. Но в более сложных случаях, где обработка данных была не столь тривиальной, скорость обработки падала чуть ли не в 10 раз. А это, кстати, не смешно. Особенно не смешно то, что профайлить что-либо в таком случае — гиблый номер, т.к. скорость очень сильно и нетривиально зависит от окружения.

BZ>варианты — данные вытесняются из кеша/озу, тред вытесняется с процессора (насколько я помню у виндов шедулинг был порциями по 20 мс минимум), программа начинает auto-gc (+RTS -q, кажись)

BZ>окружение-то какое? ездействующая юзерская машина или сервер за $5/month?

Все работает на отдельной машине под Linux, другие программы едят мало.

Данные маленькие (строчки длиной до 5000 символов), в кеш все должно влезать хорошо. И главное, данные-то в обоих случаях абсолютно идентичны. Т.е. на вылезание за пределы кеша не похоже.
Тред мог бы вытесниться, но:
1. такое скорее всего произошло бы не во время выполнения обработки сообщения, а когда программа сделала блокирующий вызов на получение нового. А это бы не повлияло на именно скорость обработки данных (по сути я меряю скорость десяти reverse для одной ByteString).
2. если это переключение проиходит сразу же после того, как задача получила очередные данные и готова их обрабатывать, то во-первых это просто дико. А во-вторых, это бы просто добавило некую константу к времени выполнения. А картинка больше похожа на пропрорциональное торможение.

Все, понял что происходило. Ну и Haskell невинен аки агнец.

У меня был включен демон, что понижал тактовую частоту при слабой нагрузке на CPU. Пока приложение ждет очередной строчки по сети, CPU не грузится и демон понижает частоту. Как только оно приходит — частота маленькая и программа тормозит. К тому моменту, как демон способен врубиться что пора бы поднять частоту — поздно, программа снова ждет следующего сообщения. Ну и конечно, если сообщения летят без остановки, то частота поднимается моментально и дальше все обрабатывается быстро.

Здравствуйте, Rtveliashvili Denys, Вы писали:

RD>Все, понял что происходило. Ну и Haskell невинен аки агнец.

RD>У меня был включен демон, что понижал тактовую частоту при слабой нагрузке на CPU. Пока приложение ждет очередной строчки по сети, CPU не грузится и демон понижает частоту. Как только оно приходит — частота маленькая и программа тормозит. К тому моменту, как демон способен врубиться что пора бы поднять частоту — поздно, программа снова ждет следующего сообщения. Ну и конечно, если сообщения летят без остановки, то частота поднимается моментально и дальше все обрабатывается быстро.

cpuspeed? выключи урода нафиг

You will always get what you always got
  If you always do  what you always did

J>Здравствуйте, Rtveliashvili Denys, Вы писали:

RD>>Все, понял что происходило. Ну и Haskell невинен аки агнец.

RD>>У меня был включен демон, что понижал тактовую частоту при слабой нагрузке на CPU. Пока приложение ждет очередной строчки по сети, CPU не грузится и демон понижает частоту. Как только оно приходит — частота маленькая и программа тормозит. К тому моменту, как демон способен врубиться что пора бы поднять частоту — поздно, программа снова ждет следующего сообщения. Ну и конечно, если сообщения летят без остановки, то частота поднимается моментально и дальше все обрабатывается быстро.

J>cpuspeed? выключи урода нафиг

Даже не так. По-умолчанию используется "ondemand" governor. Сменил его на "performance" и все пошло как по маслу.