[sisyphus] Высокий IO у jbd2

[sisyphus] Высокий IO у jbd2

[Alex Karpov]

Здравствуйте.

Не уверен, что проблема именно в сизифе, но думаю, что ничего страшного 
не случится, если задам вопрос здесь.

Сегодня с утра заметил, что непривычно долго не гаснет индикатор 
обращения к диску. Сначала подумал, что это виновата синхронизация 
Dropbox или yandex-disk, но после часа такой ерунды стало ясно, что дело 
не в них.

iotop показал, что виноват процесс jbd2, который отжирает 99.9% IO, 
причем без видимого ущерба для производительности моей системы. Вчера с 
системой были сделаны следующие изменения:
1) Установлен Яндекс.диск.
2) Обновлен сизиф, ко мне приехали новые libcairo, libcairo-gobject, 
i586-libcairo, ldap-user-tools, alterator-ulogd

Я, конечно, изменил параметры монтирования разделов с ext4, добавив 
nobarrier и на всякий случай journal_checksum, но это паллиатив. C 99.9% 
упала до 10-15%, но все равно это буквально на ровном месте и как-то 
неправильно, как мне кажется.

Есть идеи, что сломалось?

Re: [sisyphus] Высокий IO у jbd2

[Alex Karpov]

28.08.2013 17:07, Alex Karpov пишет:
> Здравствуйте.
>
> Не уверен, что проблема именно в сизифе, но думаю, что ничего 
> страшного не случится, если задам вопрос здесь.
> .....
> Есть идеи, что сломалось?
Виноват оказался ulogd. Я не знал, что он у меня был запущен, но никогда 
от него никаких проблем не было. Но вот после вчерашнего обновления он 
себя повел безобразно. Его отключение все вернуло в норму.

Re: [sisyphus] Высокий IO у jbd2

[Igor Zubkov]

2013/8/29 Alex Karpov:
> Виноват оказался ulogd. Я не знал, что он у меня был запущен, но никогда от
> него никаких проблем не было. Но вот после вчерашнего обновления он себя
> повел безобразно. Его отключение все вернуло в норму.

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

15: alterator-ulogd
###################################################################################################
[ 44%]
cp: error reading '/var/lib/ulogd/sqlite3.db': Input/output error
cp: failed to extend '/var/lib/ulogd/alterator_sqlite3.db': Input/output error
Error: near line 1: database disk image is malformed
Error: near line 23: database disk image is malformed
Error: near line 34: database disk image is malformed
Error: near line 36: database disk image is malformed
16: xorg-cf-files
###################################################################################################
[ 47%]

-- 
Igor Zubkov
http://hi.im/ice

Re: [sisyphus] Высокий IO у jbd2

[Mikhail Efremov]

On Thu, 29 Aug 2013 10:23:13 +0300 Igor Zubkov wrote:
> Не знаю зачем этот ulogd нужен, но последнее обновление у него было
> какое-то кривое.

alterator-ulogd и ulogd - это разные пакеты.

> 15: alterator-ulogd
> ###################################################################################################
> [ 44%]
> cp: error reading '/var/lib/ulogd/sqlite3.db': Input/output error
> cp: failed to extend '/var/lib/ulogd/alterator_sqlite3.db': Input/output error
> Error: near line 1: database disk image is malformed
> Error: near line 23: database disk image is malformed
> Error: near line 34: database disk image is malformed
> Error: near line 36: database disk image is malformed

I/O error в cp может означать что угодно, например проблемы с диском
или fs.

-- 
WBR, Mikhail Efremov

Re: [sisyphus] Высокий IO у jbd2

[Alex Karpov]

> On Thu, 29 Aug 2013 10:23:13 +0300 Igor Zubkov wrote:
>> Не знаю зачем этот ulogd нужен, но последнее обновление у него было
>> какое-то кривое.
> alterator-ulogd и ulogd - это разные пакеты.
Я умею читать.

Еще раз, факты:

1) система не проявляла никаких проблем.

2) До выключения машины были сделаны изменения п.1 и п.2 в первом моем 
письме в этом треде.

3) После первого включения машины с теми изменениями с достоверностью 
100% старт ulogd приводит к 100% загрузке IO процессом jbd2, а его 
выключение - к осмысленной загрузке. В случае запущенного ulogd 
добавление опций nobarrier и commit= ведет к снижению нагрузки до 
15%-20%, но не к полному её устранению. ulogd постоянно пишет что-то на 
уровне 10Кб/c, jbd2 не пишет вообще ничего - я специально посмотрел 
полчасика, как ведет себя система в простое.

До вчерашнего дня я и понятия не имел, что у меня запущена служба ulogd, 
хотя судя по её журналу она живет у меня с момента установки ОС.

Связаны ли п.1, 2 и 3 между собой - я не знаю. Вполне возможно, что за 
ночь (хотя я ухожу гораздо позже администраторов, а прихожу гораздо 
раньше них же) какой-то враг что-то сделал с сетью в моей конторе.
>
>> 15: alterator-ulogd
>> ###################################################################################################
>> [ 44%]
>> cp: error reading '/var/lib/ulogd/sqlite3.db': Input/output error
>> cp: failed to extend '/var/lib/ulogd/alterator_sqlite3.db': Input/output error
>> Error: near line 1: database disk image is malformed
>> Error: near line 23: database disk image is malformed
>> Error: near line 34: database disk image is malformed
>> Error: near line 36: database disk image is malformed
> I/O error в cp может означать что угодно, например проблемы с диском
> или fs.
>

Re: [sisyphus] Высокий IO у jbd2

[Alex Karpov]

> После первого включения машины с теми изменениями с достоверностью 
> 100% старт ulogd приводит к 100% загрузке IO процессом jbd2, а его 
> выключение - к осмысленной загрузке. В случае запущенного ulogd 
> добавление опций nobarrier и commit= ведет к снижению нагрузки до 
> 15%-20%, но не к полному её устранению. ulogd постоянно пишет что-то 
> на уровне 10Кб/c, jbd2 не пишет вообще ничего - я специально посмотрел 
> полчасика, как ведет себя система в простое.
Я посмотрел - обновления от 27 августа кардинально перекорежили мой 
конфиг ulogd. Старый вариант записан в ulogd.conf.bak, а не снесен 
подчистую.

Пока что единственная существенная разница, которую я нашел (diff тупо 
вываливает два полных текста конфигов, искать там разницу невозможно), 
это то, что в новом конфиге loglevel закомментирован, а в старом явно 
был равен 5. Ну и в новом присутствует stack для alterator-ulogd, в то 
время как в старом все это в принципе отсутствовало.

Re: [sisyphus] Высокий IO у jbd2

[Mikhail Efremov]

On Thu, 29 Aug 2013 11:29:11 -0500 Alex Karpov wrote:
> > После первого включения машины с теми изменениями с достоверностью 
> > 100% старт ulogd приводит к 100% загрузке IO процессом jbd2, а его 
> > выключение - к осмысленной загрузке. В случае запущенного ulogd 
> > добавление опций nobarrier и commit= ведет к снижению нагрузки до 
> > 15%-20%, но не к полному её устранению. ulogd постоянно пишет
> > что-то на уровне 10Кб/c, jbd2 не пишет вообще ничего - я специально
> > посмотрел полчасика, как ведет себя система в простое.
> Я посмотрел - обновления от 27 августа кардинально перекорежили мой 
> конфиг ulogd. Старый вариант записан в ulogd.conf.bak, а не снесен 
> подчистую.

Это конфиг для ulogd2 с перенесенными настройками, с конфигом от ulogd1
он работать не будет.
Старый ulogd.conf.bak можно удалять, в принципе.

> Пока что единственная существенная разница, которую я нашел (diff
> тупо вываливает два полных текста конфигов, искать там разницу
> невозможно), это то, что в новом конфиге loglevel закомментирован, а
> в старом явно был равен 5. Ну и в новом присутствует stack для
> alterator-ulogd, в то время как в старом все это в принципе
> отсутствовало.

Loglevel по умолчанию 5, явно можно не задавать. Смотреть diff
бессмысленно, формат конфига изменился почти полностью.

-- 
WBR, Mikhail Efremov

Re: [sisyphus] Высокий IO у jbd2

[Alex Karpov]

30.08.2013 05:00, Mikhail Efremov пишет:
>> Пока что единственная существенная разница, которую я нашел (diff
>> тупо вываливает два полных текста конфигов, искать там разницу
>> невозможно), это то, что в новом конфиге loglevel закомментирован, а
>> в старом явно был равен 5. Ну и в новом присутствует stack для
>> alterator-ulogd, в то время как в старом все это в принципе
>> отсутствовало.
> Loglevel по умолчанию 5, явно можно не задавать. Смотреть diff
> бессмысленно, формат конфига изменился почти полностью.
>
Я в принципе так и думал, особенно после сравнения двух файлов.

Теперь вот только для себя прояснить вопрос осталось - это баг или фича? 
В том плане, что это нормально, что связка ulogd2+ext4 так нервно реагирует?

Re: [sisyphus] Высокий IO у jbd2

[Alex Karpov]

> 2013/8/29 Alex Karpov:
>> Виноват оказался ulogd. Я не знал, что он у меня был запущен, но никогда от
>> него никаких проблем не было. Но вот после вчерашнего обновления он себя
>> повел безобразно. Его отключение все вернуло в норму.
> Не знаю зачем этот ulogd нужен, но последнее обновление у него было
> какое-то кривое.
Нет, у меня обновление прошло без проблем.

Re: [sisyphus] Высокий IO у jbd2

[Mikhail Efremov]

On Wed, 28 Aug 2013 19:21:40 -0500 Alex Karpov wrote:
> 28.08.2013 17:07, Alex Karpov пишет:
> > Здравствуйте.
> >
> > Не уверен, что проблема именно в сизифе, но думаю, что ничего 
> > страшного не случится, если задам вопрос здесь.
> > .....
> > Есть идеи, что сломалось?
> Виноват оказался ulogd. Я не знал, что он у меня был запущен, но никогда 
> от него никаких проблем не было. Но вот после вчерашнего обновления он 
> себя повел безобразно. Его отключение все вернуло в норму.

После вчерашнего обновления могли быть перенесены настройки из старого
конфига (если они создавались при установке инсталлер-фичей). После
этого ulogd должен работать также как и раньше, записывать все в sqlite
ДБ. И тут все зависит от трафика: чем больше трафик, тем больше
обращений к диску. Мне не ясно как при тех же настройках ulogd2 и
таком же трафике может создавать большую нагрузку, чем ulogd1.

-- 
WBR, Mikhail Efremov