Name Resolution 에 따른 DB 접속 지연 현상

DNS 조회 문제로 인해 데이터베이스 서버 연결이 느려지는 경우가 있습니다.

막상 마주하면 당황스럽고 엉뚱한 방향으로 접근 할 수 있는 문제인데요. 제가 경험한 해결 방법을 정리해보려고 합니다.

 

Name Resolution은 도메인 네임을 IP 주소(gethostbyname)로 또는 IP 주소를 도메인 네임(gethostbyaddr, Reverse DNS lookup)으로 변환하는 프로세스를 의미합니다. 변환을 수행하기 위해 DNS나 /etc/hosts 파일을 조회하게 됩니다.

 

AIX의 Name Resolution은 netsvc.conf 파일 또는 환경변수 NSORDER 에 정의된 값을 참조하여 수행됩니다.

예를 들어 dbaccess 프로그램으로 DB에 연결 요청을 하면 소켓 API인 gethostbyname (또는 gethostname) 함수가 호출되는 것을 확인 할 수 있는데요. 이 과정에서 /etc/netsvc.conf 에 정의된 순서대로 호스트 이름 및 Internet Protocal (IP) 주소를 해석합니다. 필요에 따라 환경변수 NSORDER 를 정의하여 기존의 옵션을 덮어 쓸 수 있습니다.

hosts = local hosts = local , nis, bind hosts = local4 , bind4

/etc/netsvc.conf 파일 설정 예시

truss 유틸리티를 사용해 dbaccess로 DB 연결을 요청하는 동안 어떤 시스템 호출이 수행되는지 확인해 보았습니다.

로컬에서 실행해서인지 gethostname이 호출이 되네요.

$ cat /etc/resolv.conf $ export NSORDER=local,bind $ onmode -ky; oninit $ timex dbaccess sysmaster@myserver -e real 75.10 user 0.02 sys  0.03 $ $ truss -d -o outfile dbaccess sysmaster@myserver -e $ cat outfile ... 0.6781:        gethostname(0x0FFFFFFFFFFF86C8, 1024) = 0 0.6785:        __libc_sbrk(0x0000000000010020)  = 0x0000000111256700 0.6789:        socket(1, 1, 0)                  = 6 0.6793:        kfcntl(6, F_SETFD, 0x0000000000000001) = 0 0.6798:        connext(6, 0x0FFFFFFFFFFFA0C8, 1025) Err#2  ENOENT 0.6802:        close(6)                         = 0 0.6805:        _thread_self()                   = 30605535 0.6810:        kopen("/etc/hosts", O_RDONLY)    = 6 0.6814:        kioctl(6, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY 0.6818:        kfcntl(6, F_SETFD, 0x0000000000000001) = 0 0.6823:        kioctl(6, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY 0.6826:        kread(6, " 1 2 7 . 0 . 0 . 1   l o".., 4096) = 38 0.6830:        kread(6, " 1 2 7 . 0 . 0 . 1   l o".., 4096) = 0 0.6834:        socket(1, 1, 0)                  = 7 0.6838:        kfcntl(7, F_SETFD, 0x0000000000000001) = 0 0.6842:        connext(7, 0x0FFFFFFFFFFFA0C8, 1025) Err#2  ENOENT 0.6846:        close(7)                         = 0 0.6850:        _thread_self()                   = 30605535 0.6854:        socket(2, 2, 0)                  = 7 0.6858:        getsockopt(7, 65535, 4104, 0x0FFFFFFFFFFF7FA4, 0x0FFFFFFFFFFF7FA0) = 0 0.6862:        connext(7, 0x09001000A00236F0, 16) = 0 0.6866:        _esend(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x0000000000000000) = 22 0.6871:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) = 1 0.6875:        _enrecvfrom(7, 0x0FFFFFFFFFFFA220, 1024, 0, 0x0FFFFFFFFFFF8830, 0x0FFFFFFFFFFF8058, 0x0000000000000000) Err#79 ECONNREFUSED 0.6879:        close(7)                         = 0 0.6883:        socket(24, 2, 0)                 = 7 0.6887:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A0023D0C, 28, 0x0000000000000000) = 22 2.6895:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) (sleeping...) 2.6895:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) = 0 5.6897:        close(7)                         = 0 5.6901:        socket(2, 2, 0)                  = 7 5.6905:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A00236F0, 16, 0x0000000000000000) = 22 7.6913:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) (sleeping...) 7.6913:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) = 0 10.6915:        close(7)                        = 0 10.6919:        socket(24, 2, 0)                = 7 10.6923:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A0023D0C, 28, 0x0000000000000000) = 22 12.6931:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) (sleeping...) 12.6931:        _poll(0x0FFFFFFFFFFF8070, 1, 5000) = 0 15.6933:        close(7)                        = 0 15.6937:        socket(2, 2, 0)                 = 7 15.6941:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A00236F0, 16, 0x0000000000000000) = 22 17.6949:        _poll(0x0FFFFFFFFFFF8070, 1, 10000) (sleeping...) 17.6949:        _poll(0x0FFFFFFFFFFF8070, 1, 10000) = 0 25.6951:        close(7)                        = 0 25.6955:        socket(24, 2, 0)                = 7 25.6959:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A0023D0C, 28, 0x0000000000000000) = 22 27.6967:        _poll(0x0FFFFFFFFFFF8070, 1, 10000) (sleeping...) 27.6967:        _poll(0x0FFFFFFFFFFF8070, 1, 10000) = 0 35.6969:        close(7)                        = 0 35.6974:        socket(2, 2, 0)                 = 7 35.6978:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A00236F0, 16, 0x0000000000000000) = 22 37.6985:        _poll(0x0FFFFFFFFFFF8070, 1, 20000) (sleeping...) 37.6985:        _poll(0x0FFFFFFFFFFF8070, 1, 20000) = 0 55.6988:        close(7)                        = 0 55.6992:        socket(24, 2, 0)                = 7 55.6996:        _esendto(7, 0x0FFFFFFFFFFF8ED0, 22, 0, 0x09001000A0023D0C, 28, 0x0000000000000000) = 22 57.7003:        _poll(0x0FFFFFFFFFFF8070, 1, 20000) (sleeping...) 57.7003:        _poll(0x0FFFFFFFFFFF8070, 1, 20000) = 0 75.7006:        close(7)                        = 0 75.7010:        close(6)                        = 0

truss 유틸리티 실행 예시

dbaccess 실행에 75초가 소요되었고, truss 추적 결과에서는 /etc/hosts 파일을 조회하는 동안 몇 차례의 대기시간이 발생한 것을 확인할 수 있습니다. truss 추적 결과의 모든 대기시간을 합산하면 (5 + 5 + 5 + 10 + 10 + 20 + 20) = 75초 이므로 /etc/hosts 파일을 참조하는 시간이 대기시간의 대부분임을 알 수 있습니다.

Informix 로그에서는 동일한 시간대에 아래와 같이 DNS 응답 속도가 느리다고 표시되네요.

17:38:54  WARNING: Detected slow or failing DNS service response 1 time(s).

 

 

네임서버 설정이 되지 않은 상태이므로 nslookup 명령으로 네임 서버 조회가 되는지 확인하는 것은 의미가 없어 보입니다. 명확하게 DNS 조회에 문제가 있을때는 네임 서버를 재시작하거나 DNS 설정을 제거하면 접속 지연이 해결되기도 했었는데 이 경우는 다른 케이스로 보아야 할 것 같습니다.

Are there any name resolution problems? Because the rembak client and the lpd server may do a gethostbyname call, it is important that both the client and the server can recognize each other not only by address but also by name. If you are using DNS, then use the nslookup command to check the name lookup both by address and by name. If you are not using a Domain Name Server (DNS), then use the host command instead of nslookup. If you fail to get the same results from the address and the name, or if you do not get a name at all, then either add the names to the DNS, or to the /etc/hosts file.

IBM Redbook (Problem Solving and Troubleshooting in AIX 5L)

IBM 문서를 조사해보니 dbaccess는 gethostbyname 함수가 IPv4만 지원하는 반면, getaddrinfo 함수는 IPv4 및 IPv6 주소를 모두 지원한다고 합니다. 하지만 truss 추적 결과에는 getaddinfo 함수가 보이지않아 정확한 작동 방식은 문서를 좀 더 찾아봐야 알 것 같습니다.

By default, dbaccess passes value “AF_INET6” for addrinfo.ai_family. The ai_family field indicates the protocol family associated with the request, and will be PF_INET6 for IPv6 or PF_INET for IPv4. If the ai_family set to AF_INET6 (IPv6) the getaddrinfo() will search the DNS every time. If the ai_family set to AF_INET, then it don't query the DNS server. You can consult the 'man' page for getaddrinfo() for detailed information.

A possible cause for slow connection to the database server

 

먼저 기존의 네트워크 정보를 netstat 명령으로 확인해보면, 네트워크 인터페이스인 en0 에 IPv4 주소만 할당되어 있고 IPv6 주소는 보이지 않는 상태입니다. loopback 인터페이스에는 IPv6 주소(::1)가 보이네요.

$ netstat -ni
Name  Mtu   Network     Address           Ipkts Ierrs    Opkts Oerrs  Coll
en0   1500  link#2      0.6.29.4.55.ec   39192470     0 19061203     0     0
en0   1500  9.3.230.64  9.3.230.117      39192470     0 19061203     0     0
lo0   16896 link#1                        6368677     0  6368676     0     0
lo0   16896 127         127.0.0.1         6368677     0  6368676     0     0
lo0   16896 ::1%1                         6368677     0  6368676     0     0

 

autoconf6 명령으로 IPv6 네트워크 인터페이스를 생성합니다. netstat 명령으로 다시 확인한 결과 IPv6 주소를 확인할 수 있습니다. en0 인터페이스의 IPv6 주소를 /etc/hosts 에 등록하고 DB 서버를 재시작한 후에는 DB 연결에 지연이 없었습니다.

$ autoconf6
$ netstat -ni
Name  Mtu   Network     Address           Ipkts Ierrs    Opkts Oerrs  Coll
en0   1500  link#2      0.6.29.4.55.ec   39192470     0 19061203     0     0
en0   1500  9.3.230.64  9.3.230.117      39192470     0 19061203     0     0
en0   1500  fe80::206:29ff:fe04:55ec     39192470     0 19061203     0     0
lo0   16896 link#1                        6368677     0  6368676     0     0
lo0   16896 127         127.0.0.1         6368677     0  6368676     0     0
lo0   16896 ::1%1                         6368677     0  6368676     0     0

$ cat /etc/hosts
127.0.0.1 localhost
9.3.230.117 lpar
fe80::206:29ff:fe04:55ec lpar

이 외에도 /etc/netsvc.conf 파일의 설정에서 local4, bind4 와 같이 IPv4 주소만 참조하도록 설정하거나, Informix 에서 IPv6 주소를 사용하지 않도록 $INFORMIXDIR/etc/IFX_DISABLE_IPV6 파일을 생성해주는 방안으로도 연결 지연이 해소되었습니다. DB 접속 지연이 있는 경우 DNS 상태뿐만 아니라 IPv6 설정여부를 확인하시면 도움이 되실겁니다.

 

https://www.ibm.com/support/pages/possible-cause-slow-connection-database-server

A possible cause for slow connection to the database server

https://www.ibm.com/support/pages/connections-ids-hang

Connections to IDS hang

https://www.ibm.com/support/pages/slow-connect-time-informix-when-using-tcpip

Slow connect time to Informix when using TCP/IP

https://www.ibm.com/docs/en/informix-servers/14.10?topic=communication-informix-support-ipv6-addresses 

Informix support for IPv6 addresses