Конференция "WinAPI" » Многопоточность. Запись логов
 
  • Дмитрий (14.09.13 19:41) [0]
    Вроде-бы стандартная ситуация. Создаю файл и пытаюсь в него писать. Из основного модуля все работает. Из потока, действия которого мне тоже надо логгировать - сразу крашится. Как можно решить?

    AssignFile(log,GetCurrentDir+'\log.txt');
    if FileExists(GetCurrentDir+'\log.txt') then
    Reset(Log) else Rewrite(log);

    В потоке:
     Writeln(log,TimeToStr(now)+' Connected');
  • megavoid © (14.09.13 19:52) [1]
    Попахивает битвой за дескриптор :)

    Как решить - писать из одного места, оформить процедурой, постараться не юзать паскалевские методы работы с файлами. Где log определена, как именно?
  • sammy (14.09.13 19:56) [2]
    используй  синхронизацию  
    http://www.delphi-manual.ru/synchronize.php
  • Дмитрий (14.09.13 19:57) [3]
    глобальный var основной формы. log:text;
  • sammy (14.09.13 19:57) [4]
    код  в процедуре будет выполнен в основном потоке и проблем быть не должно
  • Дмитрий (14.09.13 20:00) [5]
    sammy спасибо, но это надо гонять данные из потока в основной и там уже записывать. Думал обойтись без этого.
  • Дмитрий (14.09.13 20:02) [6]
    Поясню немножко. Поток создает idHTTP и шлет запрос. Ждет ответа и передает его основной форме через Synchronize(MainForm.Update); Мне хотелось-бы скидывать данные из потока в чистом виде до отправки (что посылает) и после отправки (что пришло).  Видимо придется передавать их все основной форме :(
  • DVM © (14.09.13 21:35) [7]

    > Видимо придется передавать их все основной форме :(

    Тебе же написали про синхронизацию доступа к файлу или куда ты там логгируешь. Синхронизация это не только Synchronize и не только с GUI потоком. Выкинь паскалевские файлы, возьми TFileStream и синхронизируй запись в него критической секцией.
  • sammy (14.09.13 23:18) [8]
    в потоке создай такую же переменную, передавай в поток значение log и пиши в него через метод который вызываешь в synchronization, прям в потоке напишешь  
    procedure thread.log;
    begin
    Writeln(log,TimeToStr(now)+' Connected');
    end;

    procedure thread.execute;
    begin
    synchronize(log);
    end;

    p.s. прошу прошения за ошибки, день программиста вчера был :)))
  • Alaska (26.10.17 16:26) [9]
    TLogger=class(TThread)
    protected
     CS:TCriticalSection;
     FInterval:integer;
     buff:TStringList;
     LogName:String;
     procedure Execute;override;
    public
     constructor Create(FileName:String;MaxCnt:integer;interval:integer);
     destructor  Free;
     procedure   Log(S:String);
     procedure   Flush;
    end;

    { TLogger }

    constructor TLogger.Create(FileName: String; MaxCnt, interval: integer);
    procedure recren(n:string;lvl:integer);
    begin
     if (lvl=-1) then
       begin
        if (FileExists(n)and FileExists(n+'.0')) then recren(n,0);
       RenameFile(n,n+'.0');
       end else
     if lvl>MaxCnt then DeleteFile(n+'.'+IntToStr(lvl)) else
      begin
       if FileExists(n+'.'+IntToStr(lvl+1)) then recren(n,lvl+1);
       RenameFile(n+'.'+IntToStr(lvl),n+'.'+IntToStr(lvl+1));
      end;
    end;
    begin
    MaxCnt:=MaxCnt-2;
    recren(FileName,-1);
    LogName:=FileName;
    FInterval:=interval;
    buff:=TStringList.Create;
    CS:=TCriticalSection.Create;
    Inherited Create(FInterval<100);
    end;

    procedure TLogger.Execute;
    begin
     while true do
      begin
        Flush;
        sleep(FInterval);
      end;
    end;

    procedure TLogger.Flush;
    var i,l:integer;T:Text;
    begin
     CS.Enter;
     AssignFile(T,LogName);
     if FileExists(LogName) then
     Append(T)
     else
     Rewrite(T);
     l:=buff.Count-1;
     for i:=0 to l do Writeln(T,buff[i]);
     buff.Clear;
     CloseFile(T);
     CS.Leave;
    end;

    destructor TLogger.Free;
    begin
    Suspend;
    Flush;
    CS.Free;
    buff.Free;
    end;

    procedure TLogger.Log(S: String);
    begin
     CS.Enter;
     buff.Add(S);
     CS.Leave;
    end;
  • rrrrrrr © (26.10.17 16:53) [10]
    о божечки. как длинно-то .....

    unit LogUnit;

    interface

    procedure Log(const AMsg : string; const AParam : string = '');

    implementation

    uses Windows, Classes, SysUtils,SyncObjs;

    var LogName : string;
       cs : TCriticalSection = nil;

    procedure Log(const AMsg : string; const AParam : string = '');
    var F:Text;
    begin
    try
     cs.Enter;
     Assign(F,LogName);
     if FileExists(LogName) then Append(F) else Rewrite(F);
     Writeln(F,FormatDateTime('dd.mm.yyyy hh:mm:ss',Now),#9,GetCurrentThreadID,#9,AMsg,#9,AParam);
    finally
     Close(F);
     cs.Leave;
    end;
    end;

    initialization
    cs := TCriticalSection.Create;
    LogName := ChangeFileExt(Trim(ParamStr(0)),'.log');
    finalization
    cs.Free;
    end.

  • han_malign © (27.10.17 10:36) [11]

    > о божечки. как длинно-то .....

    ...
    h:= CreateFile(PChar(filePath), {FILE_APPEND_DATA=}$4, FILE_SHARE_READ or FILE_SHARE_WRITE, nil, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, 0);
    if( h <> INVALID_HANDLE_WALUE )then begin
       WriteFile(h, pointer(str)^, Length(str), dwX, 0);
       CloseHandle(h);
    end;


    для libc соответсвтенно open(..., O_RDWR or O_CREAT or O_APPEND, ... )/write/close

    F:Text - для сценария открытие, запись, закрытие - однозначный криминал - т.к. там промежуточный буфер.(TFileStream - еще хуже, т.к. еще дополнителные операции выделения/освобождения памяти под экземпляр и буфер)

    причём для O_APPEND - атомарность однократного write гарантируется документацией, для FILE_APPEND_DATA - явно не документированно, но пока сбоев не было...
  • rrrrrrr © (27.10.17 10:58) [12]
    да пофик вообще.
    модулю этому лет 18-19 , засунут он в папку коммон и трудится он круглые сутки прилинкованый к фик знает скольки процессам созданным за все это время.

    был бы там хоть малейший реальный криминал, я бы уже об этом знал
  • Pavia © (27.10.17 15:35) [13]

    > F:Text - для сценария открытие, запись, закрытие - однозначный
    > криминал - т.к. там промежуточный буфер.

    Если логов пишется много и выкинуть буфер, то это приведёт к проседанию программы по скорости в разы. Так что без-буфера ну никак нельзя.


    > был бы там хоть малейший реальный криминал

    Обработка ошибок открытия файла сделана неверно. Лучше TEXT заменить на TFileStream/TMemoryStream
  • rrrrrrr © (27.10.17 15:51) [14]
    там нет обработки ошибок открытия файла
  • Игорь Шевченко © (27.10.17 20:45) [15]

    > F:Text - для сценария открытие, запись, закрытие - однозначный
    > криминал - т.к. там промежуточный буфер


    Чего ?
  • han_malign © (30.10.17 17:51) [16]

    > Чего ?

    function _WriteBytes(var t: TTextRec; const b; cnt : Longint): Pointer;
    {$IFDEF PUREPASCAL}
    var
     P: PChar;
     RemainingBytes: Longint;
     Temp: Integer;
    begin
     Result := @t;
     if t.Mode <> fmOutput and not TryOpenForOutput(t) then Exit;

     P := t.BufPtr + t.BufPos;
     RemainingBytes := t.BufSize - t.BufPos;
     while RemainingBytes <= cnt do
     begin
       Inc(t.BufPos, RemainingBytes);
       Dec(cnt, RemainingBytes);
       Move(B, P^, RemainingBytes);
       Temp := TTextIOFunc(t.InOutFunc)(t);
       if Temp <> 0 then
       begin
         SetInOutRes(Temp);
         Exit;
       end;
       P := t.BufPtr + t.BufPos;
       RemainingBytes := t.BufSize - t.BufPos;
     end;
     Inc(t.BufPos, cnt);
     Move(B, P^, cnt);
    end;
    {$ELSE}
    ...




    > > F:Text - для сценария открытие, запись, закрытие ...
    > Если логов пишется много и выкинуть буфер, то это приведёт к проседанию программы по скорости в разы. Так что без-буфера ну никак нельзя.

     TTextBuf = array[0..127] of Char;
    - этот буфер полезен исключительно для форматирования классического типизированного вывода через Write/Writeln...
    Потоковый вывод(текстовой информации) и аварийные логи это немного разные задачи...
    И мне пока никто убедительно не смог показать, что его буферизация работает лучше файлового кэша Windows, особенно при конкуретной записи в один файл из нескольких потоков(и тем более процессов)...
    Буфер даёт весомое увеличение скорости - если выровнен на границу страницы памяти, причём не только по размеру, но и по смещению(и в этом случае небольшой добавочный выигрыш даёт FILE_FLAG_NO_BUFFERING).
  • Игорь Шевченко © (30.10.17 18:13) [17]
    han_malign ©   (30.10.17 17:51) [16]

    У меня собственно вызвала удивление процитированная фраза. Потому что при закрытии этот буфер (и все другие) записывается в файл (в кеш системы, на диск, неважно).
  • Игорь Шевченко © (30.10.17 18:15) [18]
    Кстати. Сам пользуюсь ведением протокола, аналогично [10], с заменой критической секции на mutex (у меня несколько процессов пишут в один файл), никаких тормозов не наблюдал.
  • Eraser © (30.10.17 23:02) [19]
    смотря какой объем нужно логировать. там, где большой поток данных лучше использовать отдельный поток для сброса данных на диск. так как из-за антивирусов могут появится огромные просадки в процедуре логирования, сталкивался с таким.
  • Игорь Шевченко © (31.10.17 10:35) [20]
    Eraser ©   (30.10.17 23:02) [19]


    > могут появится огромные просадки в процедуре логирования,
    >  сталкивался с таким


    Я не сталкивался. Если кто протоколирует большой объем в файлах на диске, весьма разумно будет задать ему вопрос: а нафига ?

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

    Что-то тут не так.
  • Eraser © (31.10.17 14:55) [21]

    > Игорь Шевченко ©   (31.10.17 10:35) [20]


    > Если кто протоколирует большой объем в файлах на диске,
    > весьма разумно будет задать ему вопрос: а нафига ?

    Большой объем - понятие растяжимое. В моем случае это высоконагруженный сервер (около сотни тысяч одновременных соединений) на базе IOCP. Если в рабочем потоке использовать прямое логирование на диск, это дает серьезную деградацию производительности, если не подводит память, даже без антивируса. Собственно, это в любой статье по IOCP написано, что в рабочих потоках не должно быть блокирующих, на хоть сколько то заметное время вызовов, да и из здравого смысла это понятно. Даже если логировать исключительно только факт соединения. Представьте, когда одновременно нужно записать несколько десятков тысяч записей из 30 потоков, допустим, после перезапуска сервера.


    > И потом мне крайне странно поведение антивируса, который
    > а) не может быть настроен на исключения б) занимается анализом
    > файла при каждой его модификации.

    не правильно заставлять юзеров что-то там настраивать. хотя, в моем случае, ПО не для сторонних юзеров.

    скорее всего, с данной проблемой столкнутся единицы, но, тем не менее, она есть.
  • Игорь Шевченко © (31.10.17 18:30) [22]
    Eraser ©   (31.10.17 14:55) [21]

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

    Я в [18] говорил о некоем alert.log по образу и подобию Oracle, большое количество информации там может появится в случае какой-то отладочного вывода, но, тем не менее, все равно, тормозов я не наблюдал. Другие протоколы, штатные, пишутся отдельным процессом (а то и несколькими, в зависимости от нагрузки) в базу данных, в электронную почту и т.п., а не на диск. Но и там особо информации немного, потому что писать огромные логи лично я не вижу причины. Возможно, в каких-то задачах это и оправдано.
    И еще раз - реализация зависит от задачи, нет тут серебряной пули.
  • Eraser © (31.10.17 22:25) [23]

    > Игорь Шевченко ©   (31.10.17 18:30) [22]

    ну автор то не указал, что именно он логирует и в каком объеме.
    простое логирование в т.ч. крэш лог сделаны просто, примерно так, как тут уже показывали

    function InternalAppendLogToFile(const AMsg: string): Boolean;
    var
     fText: TextFile;
     sFileName: string;
    begin
     Result := False;

     try
       sFileName := IncludeTrailingPathDelimiter(ExtractFilePath(ParamStr(0)));
       if not DirectoryExists(sFileName + 'Logs') then
         MkDir(sFileName + 'Logs');
       sFileName := sFileName + 'Logs\' + _sExeName + '_' + FormatDateTime('yyyy_mm', Now) +
         '_log.txt';
     except
       Exit;
     end;

     EnterCriticalSection(_csUniversalLog);
     try
       AssignFile(fText, sFileName);
       if FileExists(sFileName) then
         Append(fText)
       else
         Rewrite(fText);
       try
         Writeln(fText, AMsg);
       finally
         CloseFile(fText);
       end;

       Result := True;
     finally
       LeaveCriticalSection(_csUniversalLog);
     end;
    end;

    function AppendLog(const AMsg: string; AForceToFile: Boolean = False): Boolean;
    var
     sText: string;
    begin
     Result := False;

     sText := FormatDateTime('dd-mm-yyyy_hh:nn:ss:zzz', Now) + '#T:' + AMsg;
     OutputDebugString(PChar(sText));

     {$IFDEF USE_FILE}
     Result := InternalAppendLogToFile(sText);
     {$ENDIF}

     if (not Result) and AForceToFile then
       Result := InternalAppendLogToFile(sText);
    end;
  • han_malign © (01.11.17 10:50) [24]

    > Собственно, это в любой статье по IOCP написано, что в рабочих
    > потоках не должно быть блокирующих, на хоть сколько то заметное
    > время вызовов

    - в IOCP кстати есть неочевидный нюансик - зачем нужен параметр NumberOfConcurrentThreads, если можно просто не создавать лишних потоков:
    - если количество активных потоков ассоциированных с одним портом уже NumberOfConcurrentThreads, но один из потоков переходит в режим ожидания не по причине GetQueuedCompletionStatus - например на ожидании другой I/O операции, то разблокируется еще один поток(в результате чего в некоторые моменты времени количество активных потоков может быть больше NumberOfConcurrentThreads)...

    ...
    This is one reason to have your application create more threads in its thread pool than the concurrency value.
  • Alex Konshin © (03.12.17 21:27) [25]
    > Eraser ©   (31.10.17 14:55) [21]
    Согласен, что такое иногда нужно и что неверное решение очень сильно (иногда на порядки) снижает производительность.
    В таком случае логирование нужно делать в отдельном треде с входной очередью-буфером, которая либо синхронизирована, либо поддерживает асинхронное добавление без бликировки. Тред выбирает сообщения из очереди и пишет в выходной буфер. Буфер сбрасывается на диск при заполнении или после короткой задержки (чтоб не инициировалась запись слишком часто и мелкими порциями). Сама запись на диск может осуществляться либо ещё в одном отдельном треде или с помощью операций асинхроной записи.

    Уже не помню, делал ли я так где-нибудь на Delphi, но на Java я точно такое реализовывал в нескольких проектах.
  • Alex Konshin © (03.12.17 21:27) [25]
    > Eraser ©   (31.10.17 14:55) [21]
    Согласен, что такое иногда нужно и что неверное решение очень сильно (иногда на порядки) снижает производительность.
    В таком случае логирование нужно делать в отдельном треде с входной очередью-буфером, которая либо синхронизирована, либо поддерживает асинхронное добавление без бликировки. Тред выбирает сообщения из очереди и пишет в выходной буфер. Буфер сбрасывается на диск при заполнении или после короткой задержки (чтоб не инициировалась запись слишком часто и мелкими порциями). Сама запись на диск может осуществляться либо ещё в одном отдельном треде или с помощью операций асинхроной записи.

    Уже не помню, делал ли я так где-нибудь на Delphi, но на Java я точно такое реализовывал в нескольких проектах.
  • Дмитрий Белькевич © (03.12.17 23:04) [26]

    > И потом мне крайне странно поведение антивируса, который
    > а) не может быть настроен на исключения б) занимается анализом
    > файла при каждой его модификации.
    >


    Антивирусы вообще редкие каки. Каких уж чудес я с ними не видел.

    Немного в тему. У нас на одной из установок периодически установка атрибутов (FileSetAttr) вывешивает гуй, нашли с помощью эврики. Ладно бы еще запись в файл. Грешим, правда, скорее на виртуалку. Пришлось выносить в отдельный поток.
  • Дмитрий Белькевич © (03.12.17 23:04) [26]

    > И потом мне крайне странно поведение антивируса, который
    > а) не может быть настроен на исключения б) занимается анализом
    > файла при каждой его модификации.
    >


    Антивирусы вообще редкие каки. Каких уж чудес я с ними не видел.

    Немного в тему. У нас на одной из установок периодически установка атрибутов (FileSetAttr) вывешивает гуй, нашли с помощью эврики. Ладно бы еще запись в файл. Грешим, правда, скорее на виртуалку. Пришлось выносить в отдельный поток.
 
Конференция "WinAPI" » Многопоточность. Запись логов
Есть новые Нет новых   [134427   +34][b:0][p:0.002]