AVK>>>Пишем все сообщения с приоритетом High и выше и все сообщения подсистемы SubsystemA с приоритетом выше Low. GZ>>В принципе прекрасно, но что это ошибка или информация — надо различать.
AVK>
Здравствуйте, AndrewVK, Вы писали:
AVK>>>Очевидно, что акценты в немалой степени пределяются опытом. На аднный момент мне не очень интересна архитектура сильно масштабируемых систем под большие нагрузки. Соотв. и сервер создавался прежде всего под задачи большой сложности, но относительно невысокой нагрузки. GZ>>Дык и я не занимаюсь серверами реального времени. AVK>Сервера реального времени под .NET?
И даже не под net. А вот масштабируемыми приходится.
Ладно, сейчас уже нет времени, уезжаю:
Сделал тест.
Testing Buffered:
Тест Writing:12 ms
RunningThread=602000 cycles; 50166 cycles in ms
Testing NotBuffered:
Тест Writing:2030 ms
RunningThread=96107000 cycles; 47343 cycles in ms
Results:
Buffered time is 0,591133004926108 %
UnBuffered cycles is 94,3726826934577 %
Фактически получается что в 200 раз быстрее работает если не открывать каждый раз. Это называется на порядки, и железом не лечится. Время выполнения параллельного потока практически одинаковое.
Текст теста:
using System;
using System.Text;
using System.Threading;
using System.IO;
using System.Diagnostics;
namespace TestWrite
{
class Program
{
string toWrite;
long timeWrite = 0;
long timeBufferedWrite;
long timeNotBufferedWrite;
long cyclesInMs;
long cyclesBuffered;
long cyclesUnbuffered;
const int writeCyclesCount = 1000;
public ManualResetEvent evStart = new ManualResetEvent(false);
public ManualResetEvent evEnd = new ManualResetEvent(false);
public void TestWriting(object o)
{
bool isBuffered = (bool)o;
evStart.WaitOne();
Stopwatch watch = Stopwatch.StartNew();
if (isBuffered)
Buffered();
else
NotBuffered();
watch.Stop();
timeWrite = watch.ElapsedMilliseconds;
evEnd.Set();
Console.WriteLine(String.Format("Тест Writing:{0} ms", watch.ElapsedMilliseconds));
}
private void Buffered()
{
using (StreamWriter writer = new StreamWriter(@"c:\test.log", true))
{
for (int i = 0; i < writeCyclesCount; i++)
{
writer.WriteLine(toWrite);
}
}
}
private void NotBuffered()
{
for (int i = 0; i < writeCyclesCount; i++)
{
using (StreamWriter writer = new StreamWriter(@"c:\test.log", true))
{
writer.WriteLine(toWrite);
}
}
}
public void RunningThread(object state)
{
evStart.WaitOne();
long j = 0;
while (j < long.MaxValue)
{
j++;
if (j % 1000 == 0)
if (evEnd.WaitOne(0, false))
break;
}
Console.WriteLine(String.Format("RunningThread={0} cycles; {1} cycles in ms", j, j / timeWrite));
cyclesInMs = j/timeWrite;
}
private void PrepareString()
{
StringBuilder sb = new StringBuilder();
for (int i = 0; i < 50; i++)
sb.Append("0123456789");
toWrite = sb.ToString();
}
public void Test()
{
PrepareString();
Console.WriteLine("Testing Buffered:");
Thread thread1 = new Thread(RunningThread);
Thread thread2 = new Thread(TestWriting);
thread2.Start(true);
thread1.Start();
evStart.Set();
thread1.Join();
thread2.Join();
cyclesBuffered=cyclesInMs;
timeBufferedWrite=timeWrite;
evStart.Reset();
evEnd.Reset();
Console.WriteLine("Testing NotBuffered:");
thread1 = new Thread(RunningThread);
thread2 = new Thread(TestWriting);
thread2.Start(false);
thread1.Start();
evStart.Set();
thread1.Join();
thread2.Join();
cyclesUnbuffered=cyclesInMs;
timeNotBufferedWrite=timeWrite;
Console.WriteLine("Results:");
Console.WriteLine("Buffered time is {0} %", (double)timeBufferedWrite*100/timeNotBufferedWrite);
Console.WriteLine("UnBuffered cycles is {0} %", (double)cyclesUnbuffered * 100 / cyclesBuffered);
}
static void Main(string[] args)
{
new Program().Test();
}
}
}
Здравствуйте, GlebZ, Вы писали:
GZ>Ладно, сейчас уже нет времени, уезжаю: GZ>Сделал тест.
GZ>
GZ>Testing Buffered:
GZ>Тест Writing:12 ms
GZ>RunningThread=602000 cycles; 50166 cycles in ms
GZ>Testing NotBuffered:
GZ>Тест Writing:2030 ms
GZ>RunningThread=96107000 cycles; 47343 cycles in ms
GZ>Results:
GZ>Buffered time is 0,591133004926108 %
GZ>UnBuffered cycles is 94,3726826934577 %
GZ>Фактически получается что в 200 раз быстрее работает если не открывать каждый раз. Это называется на порядки, и железом не лечится. Время выполнения параллельного потока практически одинаковое.
Тест был запущен под Windows 2003 сервер, на двухядерном проце.
GZ>Кое что допишу по тесту после.
И что оно показало:
1. При буферизованной записи 1 мБ информации результат 12 ms. Для подавляющего кол-ва приложений/запросов — это пренебрежимо небольшая величина, и ею можно пренебречь и вообще пользоваться синхронным вызовом сброса.
2. Выполнение не тормозится в обоих случаях в случае многопроцессорности. В случае буферизации есть даже выигрыш, однако пренебрежительно небольшой. В случае же однопроцессорности (или можно говорить о нехватке процессоров относительно потоков) выигрыш больше.(см внизу).
3. Определяющей является именно латентность при открытии закрытии файла.
4. Фактически визуально видно что при синхронном логгировании выполнение тормозится в 2-3 раза. Иногда даже на порядки. А посему становится вероятным что переполнение очереди достаточно вероятно, так как производительность основного выполнения значительно выше. Я буферизованную асинхронку не от хорошей жизни в свое время написал.
Это было для двухядерного проца. Для домашнего одноядерного P4 без всякого гипертрейдинга с Windows XP:
Testing Buffered:
Тест Writing:5 ms
RunningThread=16000 cycles; 3200 cycles in ms
Testing NotBuffered:
Тест Writing:109 ms
RunningThread=16000 cycles; 146 cycles in ms
Results:
Buffered time is 4,58715596330275 %
UnBuffered cycles is 4,5625 %
Что касается твоей очереди. Я не думаю что это хорошая идея делать асинхронную очередь как единый механизм для всех логгеров. Все таки я бы ее сделал именно как helper класс, а выбор использовать такую, или делать другую — дело разработчика. Например, я бы при наличии своего логгера не стал бы использовать именно твою асинхронность, а это приводит к отказу от твоего логгера как такового. В принципе и ты согласен что логгер по крайней мере для mail — должен кардинально различаться. Я бы сказал больше, логгер предназначенный для трассировки, и просто для показа ошибок должны различаться, и различаться в том числе по функциональности.
AVK>Что то ты путаешься в показаниях. Либо отдельный поток, либо без асинхронности, но никак не одновременно.
Поясню, если ты не смотрел сырцы файлового которые я выложил.
1. При сохранении сообщения info — оно кладется в очередь и ожидает пока таймер не сбросит очередь в файл. Если очередь заполнена, то она расширяется в два раза. Если достигнут максимум, то оно сбрасывается в текущем потоке без таймера. Учитывая что потери буферизованного сохранения малы, и это делается только при максимуме очереди, ничего криминального нет.
2. При сохранении ошибки, сообщение добавляется в очередь, и этот же поток сохраняет очередь в хранилище. С учетом того что поток генерирующий ошибки не жалко, а время сохранения буфера достаточно мало, ничего криминального в этом, опять ж,е нет.
3. Если пиковые нагрузки прошли, то через некоторое время очередь уменьшается в два раза. Пока не достигнет минимума.
4. Если файл по каким-то причинам недоступен, то логгер объявляется мертвым и перестает принимать сообщения до тех пор, пока процедура проверки не увидит что логгер восстановился. Пока логгер мертвый, сообщения не принимаются, чтобы не нагружать ресурсы сервака ошибками. Процедура проверки жив-нежив, асинхронная. И период проверки автоматически увеличивается.
При всей гибкости, сырец QueueLogger.cs — достаточно небольшой по размеру, и достаточно прост. И не зависит от типа сохранения. Это буфферизованная очередь предназначенная в большей степени для работы трассировки. Ее с таким же успехом можно использовать для базы данных. DirLogger.cs — это уже работа с файлами при использовании данной очереди. Провязаны они через наследования (делались давно и первая целевая платформа была Net 1.1).
Здравствуйте, migel, Вы писали:
M>хъ M>хм а что, были сомнения в тормознутости операций открытия закрытия файлов
Вопрос не в тормознутости а в ее количестве и общем влиянии на систему. Если влияние 2-3 раза, или даже 5-6 — это ничего. Если на порядки — значит что-то надо делать ибо железом такие обломы не исправишь. Чем больше будет кол-во сообщений(а по сути сложность системы), тем более будет влияния на общее функционирование лога.
Здравствуйте, GlebZ, Вы писали:
GZ>Что касается твоей очереди. Я не думаю что это хорошая идея делать асинхронную очередь как единый механизм для всех логгеров. Все таки я бы ее сделал именно как helper класс, а выбор использовать такую, или делать другую — дело разработчика. Например, я бы при наличии своего логгера не стал бы использовать именно твою асинхронность, а это приводит к отказу от твоего логгера как такового. В принципе и ты согласен что логгер по крайней мере для mail — должен кардинально различаться.
Ты, кажется, не понимаешь смысл этой асинхронности. Она предназначена для того, чтобы убрать из основного кода задержку на логгирование по минимуму. Для решения задачи медленной работы саого лога оно не присбособленно, эту задачу надо решать отдельно, причем в каждом логе по своему. Нужна тебе буферизация при выводе в файл — делай ее в файловом логе, нужна запись в БД для мейлера — делай в мейлере. А то, что есть в логгере экономит время основному потоку на дспетчеризации, отсечении плохих логов, и, в перспективе, на выполнении предиката фильтра для каждого лога.
GZ> Я бы сказал больше, логгер предназначенный для трассировки, и просто для показа ошибок должны различаться, и различаться в том числе по функциональности.
Для трассировки, ИМХО, хватит штатных механизмов дотнета.
GZ>1. При сохранении сообщения info — оно кладется в очередь и ожидает пока таймер не сбросит очередь в файл.
Значит асинхронно.
GZ> Если очередь заполнена, то она расширяется в два раза. Если достигнут максимум, то оно сбрасывается в текущем потоке без таймера.
Тормозя при этом основной поток?
GZ> Учитывая что потери буферизованного сохранения малы, и это делается только при максимуме очереди, ничего криминального нет.
Не, либо оно не делается либо делается в смертельной ситуации, и тогда твоя синхронность просто не нужна, либо оно делается в процессе работы, тогда это криминал.
... << RSDN@Home 1.2.0 alpha rev. 725 on Windows Vista 6.0.6000.0>>
Здравствуйте, AndrewVK, Вы писали:
AVK>Ты, кажется, не понимаешь смысл этой асинхронности. Она предназначена для того, чтобы убрать из основного кода задержку на логгирование по минимуму. Для решения задачи медленной работы саого лога оно не присбособленно, эту задачу надо решать отдельно, причем в каждом логе по своему. Нужна тебе буферизация при выводе в файл — делай ее в файловом логе, нужна запись в БД для мейлера — делай в мейлере. А то, что есть в логгере экономит время основному потоку на дспетчеризации, отсечении плохих логов, и, в перспективе, на выполнении предиката фильтра для каждого лога.
Это то понятно. В принципе я понял смысл, ничего криминального нет. Возможно ты прав, особенно в последнем предложении. Единственное что — отсечение плохих логов не стоит делать на каждом сообщении. Лог вполне может писать в какой то потерявшийся web сервис, или потерявшейся коннект к БД. В результате в лучшем случае накачаешь никому не нужных данных в другие логи, в худшем — очередь на каждом сообщении будет сидеть на чьем-то таймауте. За это время могут и пару сотен мегабайт сообщений накачать в память.
AVK>Для трассировки, ИМХО, хватит штатных механизмов дотнета.
Слишком неудобно. Собственно с этого и начал.
GZ>>1. При сохранении сообщения info — оно кладется в очередь и ожидает пока таймер не сбросит очередь в файл. AVK>Значит асинхронно.
Да. Основной режим работы асинхронный.
GZ>> Если очередь заполнена, то она расширяется в два раза. Если достигнут максимум, то оно сбрасывается в текущем потоке без таймера. AVK>Тормозя при этом основной поток? GZ>> Учитывая что потери буферизованного сохранения малы, и это делается только при максимуме очереди, ничего криминального нет. AVK>Не, либо оно не делается либо делается в смертельной ситуации, и тогда твоя синхронность просто не нужна, либо оно делается в процессе работы, тогда это криминал.
Ничего криминального нет. Криминал будет если мы под задачи логгера возьмем излишнюю память требуемые основной логике. Требования к памяти лога в силу его текстуальности выше чем полезный данные сервака. Поэтому очередь ограничена. При некотором превышении — жертвуем 8-13 ms от одного из сотен потоков. Это фигня. Практически латентность вызова БД.
Здравствуйте, GlebZ, Вы писали:
GZ>Единственное что — отсечение плохих логов не стоит делать на каждом сообщении.
Это обсуждаемо. Я уже писал, что с ходу не придумал какой то правильной политики, поэтому сделал самую прпостую. Просто задел на будущее.
AVK>>Не, либо оно не делается либо делается в смертельной ситуации, и тогда твоя синхронность просто не нужна, либо оно делается в процессе работы, тогда это криминал. GZ>Ничего криминального нет.
Не знаю Мне кажется, что программа должна прежде всего выполнять свою основную работу, а уж потом все остальное. Я вообще не сторонник работы на одном крыле — лучше сразу выявить проблемы и потребовать их устранения, нежели ковылять кое как, а потом расхлебывать последствия.
... << RSDN@Home 1.2.0 alpha rev. 725 on Windows Vista 6.0.6000.0>>
Свежая версия R.SAT — http://files.rsdn.ru/5161/R.SAT-r166.7z
Основные изменения — поддержка Моно, убрана зависимость от FW 3.5, добавлена механика хранения служебных данных на диске.
... << RSDN@Home 1.2.0 alpha 2 rev. 837 on Windows Vista 6.0.6001.65536>>
А вот масштабируемыми приходится.
