[Sysadmins] ldap долго думает...

[Sysadmins] ldap долго думает...

[Maks Re]

хай.

Установил на новые сервак server 4.0 + updates

сделал Ноду

сделал контейнер. в контейнер понял openldap

при  каждом запросе к ldap происходят тормаза в 1-2 секунды, что очень
напрягает...

/proc/user_beencounters - чист

ДНС -  в соседнем контейнере....

как диагностировать такое поведение?


-- 
С уважением,
  Макс.

Re: [Sysadmins] ldap долго думает...

[Dmitry Lebkov]

Maks Re пишет:
> хай.
> 
> Установил на новые сервак server 4.0 + updates
> 
> сделал Ноду
> 
> сделал контейнер. в контейнер понял openldap
> 
> при  каждом запросе к ldap происходят тормаза в 1-2 секунды, что очень
> напрягает...
> 
> /proc/user_beencounters - чист
> 
> ДНС -  в соседнем контейнере....
> 
> как диагностировать такое поведение?

Для начала - man slapd.conf на предмет параметра loglevel.
Hint1: http://faq.altlinux.ru/index.php?action=single&nf=1&qid=624
Hint2: можно начать с loglevel 256 в slapd.conf или -d 256 в параметрах slapd.

-- 
WBR, Dmitry Lebkov

Re: [Sysadmins] ldap долго думает...

[Maks Re]

-1 достаточно?

# date; ldapsearch -x -LLL -h 127.0.0.1  -b dc=perfect-ltd,dc=ru  -D
cn=ldapadmin,dc=perfect-ltd,dc=ru -W uid=maks; date

Wed Aug 27 16:25:23 MSD 2008

Enter LDAP Password:
dn: uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru
objectClass: posixAccount
objectClass: top
objectClass: CourierMailAlias
objectClass: CourierMailAccount
objectClass: account
userPassword:: U2VjcmV0
mail: maks@perfect-ltd.ru
maildrop: postmaster@perfect-ltd.ru
cn: Maks D.
uid: maks
uidNumber: 5001
gidNumber: 5001
homeDirectory: /var/spool/mail/maks
gecos: Maks D.
mailbox: /var/spool/mail/maks/Maildir
quota: 51200000S

Wed Aug 27 16:25:31 MSD 2008

4 секунд на запрос (3 сек на ввод пароля)? многовато..



лог запроса

Aug 27 16:22:28 ldap slapd[22089]: conn=16 op=1 SRCH
base="dc=perfect-ltd,dc=ru" scope=2 deref=0 filter="(objectClass=*)"
Aug 27 16:22:28 ldap slapd[22089]: => hdb_search
Aug 27 16:22:28 ldap slapd[22089]: bdb_dn2entry("dc=perfect-ltd,dc=ru")
Aug 27 16:22:28 ldap slapd[22089]: search_candidates:
base="dc=perfect-ltd,dc=ru" (0x00000001) scope=2
Aug 27 16:22:28 ldap slapd[22089]: => hdb_dn2idl("dc=perfect-ltd,dc=ru")
Aug 27 16:22:28 ldap slapd[22089]: => bdb_filter_candidates
Aug 27 16:22:28 ldap slapd[22089]: ^IAND
Aug 27 16:22:28 ldap slapd[22089]: => bdb_list_candidates 0xa0
Aug 27 16:22:29 ldap slapd[22089]: => bdb_filter_candidates
Aug 27 16:22:29 ldap slapd[22089]: ^IPRESENT
Aug 27 16:22:29 ldap slapd[22089]: => bdb_presence_candidates (objectClass)
Aug 27 16:22:29 ldap slapd[22089]: <= bdb_filter_candidates: id=-1
first=1 last=4
Aug 27 16:22:29 ldap slapd[22089]: <= bdb_list_candidates: id=-1 first=1 last=4
Aug 27 16:22:29 ldap slapd[22089]: <= bdb_filter_candidates: id=-1
first=1 last=4
Aug 27 16:22:29 ldap slapd[22089]: bdb_search_candidates: id=-1 first=1 last=4
Aug 27 16:22:29 ldap slapd[22089]: => test_filter
Aug 27 16:22:29 ldap slapd[22089]:     PRESENT
Aug 27 16:22:29 ldap slapd[22089]: => access_allowed: search access to
"dc=perfect-ltd,dc=ru" "objectClass" requested
Aug 27 16:22:29 ldap slapd[22089]: <= root access granted
Aug 27 16:22:29 ldap slapd[22089]: <= test_filter 6
Aug 27 16:22:29 ldap slapd[22089]: => send_search_entry: conn 16
dn="dc=perfect-ltd,dc=ru"
Aug 27 16:22:29 ldap slapd[22089]: => access_allowed: read access to
"dc=perfect-ltd,dc=ru" "entry" requested
Aug 27 16:22:29 ldap slapd[22089]: <= root access granted
Aug 27 16:22:29 ldap slapd[22089]: => access_allowed: read access to
"dc=perfect-ltd,dc=ru" "objectClass" requested
Aug 27 16:22:29 ldap slapd[22089]: <= root access granted
Aug 27 16:22:29 ldap slapd[22089]: => access_allowed: read access to
"dc=perfect-ltd,dc=ru" "dc" requested
Aug 27 16:22:29 ldap slapd[22089]: <= root access granted
Aug 27 16:22:29 ldap slapd[22089]: => access_allowed: read access to
"dc=perfect-ltd,dc=ru" "o" requested
Aug 27 16:22:29 ldap slapd[22089]: <= root access granted
Aug 27 16:22:29 ldap slapd[22089]: conn=16 op=1 ENTRY dn="dc=perfect-ltd,dc=ru"
Aug 27 16:22:29 ldap slapd[22089]: <= send_search_entry: conn 16 exit.
Aug 27 16:22:29 ldap slapd[22089]: => test_filter
Aug 27 16:22:29 ldap slapd[22089]:     PRESENT
Aug 27 16:22:29 ldap slapd[22089]: => access_allowed: search access to
"ou=People,dc=perfect-ltd,dc=ru" "objectClass" requested
Aug 27 16:22:29 ldap slapd[22089]: <= root access granted
Aug 27 16:22:29 ldap slapd[22089]: <= test_filter 6
Aug 27 16:22:30 ldap slapd[22089]: => send_search_entry: conn 16
dn="ou=People,dc=perfect-ltd,dc=ru"
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=People,dc=perfect-ltd,dc=ru" "entry" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=People,dc=perfect-ltd,dc=ru" "objectClass" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=People,dc=perfect-ltd,dc=ru" "ou" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: conn=16 op=1 ENTRY
dn="ou=people,dc=perfect-ltd,dc=ru"
Aug 27 16:22:30 ldap slapd[22089]: <= send_search_entry: conn 16 exit.
Aug 27 16:22:30 ldap slapd[22089]: => test_filter
Aug 27 16:22:30 ldap slapd[22089]:     PRESENT
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: search access to
"ou=it,ou=People,dc=perfect-ltd,dc=ru" "objectClass" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: <= test_filter 6
Aug 27 16:22:30 ldap slapd[22089]: => send_search_entry: conn 16
dn="ou=it,ou=People,dc=perfect-ltd,dc=ru"
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=it,ou=People,dc=perfect-ltd,dc=ru" "entry" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=it,ou=People,dc=perfect-ltd,dc=ru" "objectClass" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=it,ou=People,dc=perfect-ltd,dc=ru" "ou" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=it,ou=People,dc=perfect-ltd,dc=ru" "mail" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: read access to
"ou=it,ou=People,dc=perfect-ltd,dc=ru" "maildrop" requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:30 ldap slapd[22089]: conn=16 op=1 ENTRY
dn="ou=it,ou=people,dc=perfect-ltd,dc=ru"
Aug 27 16:22:30 ldap slapd[22089]: <= send_search_entry: conn 16 exit.
Aug 27 16:22:30 ldap slapd[22089]: => test_filter
Aug 27 16:22:30 ldap slapd[22089]:     PRESENT
Aug 27 16:22:30 ldap slapd[22089]: => access_allowed: search access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "objectClass"
requested
Aug 27 16:22:30 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: <= test_filter 6
Aug 27 16:22:31 ldap slapd[22089]: => send_search_entry: conn 16
dn="uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru"
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "entry" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "objectClass"
requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "userPassword"
requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "mail" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "maildrop" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "cn" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "uid" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "uidNumber" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "gidNumber" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "homeDirectory"
requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "gecos" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "mailbox" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: => access_allowed: read access to
"uid=maks,ou=it,ou=People,dc=perfect-ltd,dc=ru" "quota" requested
Aug 27 16:22:31 ldap slapd[22089]: <= root access granted
Aug 27 16:22:31 ldap slapd[22089]: conn=16 op=1 ENTRY
dn="uid=maks,ou=it,ou=people,dc=perfect-ltd,dc=ru"
Aug 27 16:22:31 ldap slapd[22089]: <= send_search_entry: conn 16 exit.
Aug 27 16:22:31 ldap slapd[22089]: send_ldap_result: conn=16 op=1 p=3
Aug 27 16:22:32 ldap slapd[22089]: send_ldap_result: err=0 matched="" text=""
Aug 27 16:22:32 ldap slapd[22089]: send_ldap_response: msgid=2 tag=101 err=0
Aug 27 16:22:32 ldap slapd[22089]: conn=16 op=1 SEARCH RESULT tag=101
err=0 nentries=4 text=
Aug 27 16:22:32 ldap slapd[22089]: daemon: activity on 1 descriptor
Aug 27 16:22:32 ldap slapd[22089]: daemon: activity on:
Aug 27 16:22:32 ldap slapd[22089]:  26r
Aug 27 16:22:32 ldap slapd[22089]:
Aug 27 16:22:32 ldap slapd[22089]: daemon: read active on 26
Aug 27 16:22:32 ldap slapd[22089]: connection_get(26)
Aug 27 16:22:32 ldap slapd[22089]: connection_get(26): got connid=16
Aug 27 16:22:32 ldap slapd[22089]: connection_read(26): checking for
input on id=16
Aug 27 16:22:32 ldap slapd[22089]: ber_get_next on fd 26 failed
errno=0 (Success)
Aug 27 16:22:32 ldap slapd[22089]: connection_read(26): input error=-2
id=16, closing.
Aug 27 16:22:32 ldap slapd[22089]: connection_closing: readying
conn=16 sd=26 for close
Aug 27 16:22:32 ldap slapd[22089]: connection_close: deferring conn=16 sd=-1
Aug 27 16:22:32 ldap slapd[22089]: daemon: epoll: listen=7
active_threads=0 tvp=NULL
Aug 27 16:22:32 ldap slapd[22089]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Aug 27 16:22:32 ldap slapd[22089]: daemon: activity on 1 descriptor
Aug 27 16:22:32 ldap slapd[22089]: daemon: activity on:
Aug 27 16:22:32 ldap slapd[22089]:
Aug 27 16:22:32 ldap slapd[22089]: daemon: epoll: listen=7
active_threads=0 tvp=NULL
Aug 27 16:22:32 ldap slapd[22089]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Aug 27 16:22:32 ldap slapd[22089]: do_unbind
Aug 27 16:22:32 ldap slapd[22089]: conn=16 op=2 UNBIND
Aug 27 16:22:32 ldap slapd[22089]: connection_resched: attempting
closing conn=16 sd=26
Aug 27 16:22:32 ldap slapd[22089]: connection_close: conn=16 sd=-1
Aug 27 16:22:32 ldap slapd[22089]: daemon: removing 26
Aug 27 16:22:32 ldap slapd[22089]: conn=16 fd=26 closed






-- 
С уважением,
  Макс.

Re: [Sysadmins] ldap долго думает...

[Dmitry Lebkov]

Maks Re пишет:
> -1 достаточно?

А подумать? Догадайся, СКОЛЬКО лишних телодвижений делает slapd
при включенном дебаге ВСЕГОПОДРЯД...

> # date; ldapsearch -x -LLL -h 127.0.0.1  -b dc=perfect-ltd,dc=ru  -D
> cn=ldapadmin,dc=perfect-ltd,dc=ru -W uid=maks; date

Тогда уж '... -w blablabla ...' для чистоты экперимента.

> Wed Aug 27 16:25:23 MSD 2008
              ^^^^^^^^
> 
> Enter LDAP Password:
[skip]
> Wed Aug 27 16:25:31 MSD 2008
> 
> 4 секунд на запрос (3 сек на ввод пароля)? многовато..
> 
> лог запроса

Судя по результатам date и таймстампу из лога -- это не лог запроса.

> Aug 27 16:22:28 ldap slapd[22089]: conn=16 op=1 SRCH
          ^^^^^^^^
> base="dc=perfect-ltd,dc=ru" scope=2 deref=0 filter="(objectClass=*)"
> Aug 27 16:22:29 ldap slapd[22089]: conn=16 op=1 ENTRY dn="dc=perfect-ltd,dc=ru"

Таки ставь loglevel 256 и еще раз 'date; ldapsearch ... -w blablabla ... ;date'.

-- 
WBR, Dmitry Lebkov

Re: [Sysadmins] ldap долго думает...

[Maks Re]

да,

>  А подумать? Догадайся, СКОЛЬКО лишних телодвижений делает slapd
>  при включенном дебаге ВСЕГОПОДРЯД...

вы правы, это здесь было узким место...
но я не понял почему на другом тазике,  где openldap крутится не в
контейнера, а как служба, и высоким уровлем лога было все ОК.

поставил 256 уровень...

а лог запроса и сам запрос - да. они были немного разыне, но картинка
не менялась...

-- 
С уважением,
  Макс.

Re: [Sysadmins] ldap долго думает...

[Dmitry Lebkov]

Maks Re пишет:
> да,
> 
>>  А подумать? Догадайся, СКОЛЬКО лишних телодвижений делает slapd
>>  при включенном дебаге ВСЕГОПОДРЯД...
> 
> вы правы, это здесь было узким место...
> но я не понял почему на другом тазике,  где openldap крутится не в
> контейнера, а как служба, и высоким уровлем лога было все ОК.

Возможно там, на другой системе:
  - по-другому настроен способ записи отладочной информации. Например
    syslog'у сказано не sync'аться посел каждого log-сообщения или запсиь
    логов вообще ведется не через syslog;
  - более быстрая дисковая подсистема/FS/что_то_там_еще;

Причин может быть множество. Рассматривать надо каждый конкретный случай.

> поставил 256 уровень...

На "боевых" системах эти логи лучше вообще отключать -- таки это средство
ОТЛАДКИ, а не штатное средство протоколирования работы сервера.

> а лог запроса и сам запрос - да. они были немного разыне, но картинка
> не менялась...

Мда. =\ В диагностике важна ЛЮБАЯ мелочь.

-- 
WBR, Dmitry Lebkov