Question

Среда

Различные приложения, использующие пул соединений jdbc: серверы приложений WebLogic 8 (и выше) и Tomcat 6, различные версии Oracle Database (от 9.2.0.7 до 10.2.0.4) на разных платформах (RHEL5.5, Solaris 9, Solari 10 и т. Д.).

Я пытаюсь понять значение следующих записей в файле журнала прослушивателя (обратите внимание на частоту):

07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59576)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59578)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59577)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59579)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59580)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59581)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59583)) * establish * <my_sid> * 0
07-DEC-2010 09:32:30 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59582)) * establish * <my_sid> * 0
07-DEC-2010 09:32:32 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59589)) * establish * <my_sid> * 0
07-DEC-2010 09:32:43 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59600)) * establish * <my_sid> * 0
07-DEC-2010 09:32:43 * (CONNECT_DATA=(SID=<my_sid>)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=<my_user>))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<my_host>)(PORT=59601)) * establish * <my_sid> * 0

Все этиприложения используют пулы соединений, v $ session.logon_time отражает время активации пула соединений (обычно время запуска сервера приложений) и ожидаемое количество соединений.

Поэтому я пытаюсь понять, что это за частые записив журнале слушателя представляют.

Являются ли эти новые новые соединения (я полагаю, что они не являются) или они просто представляют обычный трафик, который проходит через существующие соединения пула соединений (если это не так,Я не понимаю, почему порт меняется (я знаю, что слушатель перенаправляет клиента насвободный порт во время первоначального рукопожатия, но я не понимаю, почему это происходит после того, как пул соединений уже запущен)

Может ли это быть своего рода сердцебиением, при котором пул соединений не используется?

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

Вот некоторые цифры из этого конкретного файла журнала:

$ tail -1000 listener_<my_sid>.log | awk 'END {
    for (i in count)
  if (count[i] > 10)
    print i, count[i]
}
  /__jdbc__/ {
    sub(/:[^:]*$/, x, $2)
    count[$2]++
  }'
09:14 13
09:17 32
08:45 14
09:19 12
08:49 13
09:32 33
09:35 20
09:37 17
09:38 29
08:30 35
09:03 13
09:05 13
08:33 13
08:51 11
09:24 28

записи не в порядке, но здесь это не имеет значения, в чем я пытаюсь понять смысл этих 35 записей в минуту.

Я наблюдаю такое поведение в различных средах серверов приложений Java на разных сайтах клиентов и не вижу ненормального использования ресурсов из-за этого.

Сконфигурированные соединения пула соединений отображаются правильно в v$ session: например, с 50 x узлом приложения (min = max) я вижу 50 соединений x узла приложения в v $ session, v $ session.logon_time правильно отражает время, когда был запущен соответствующий узел приложения.

Тозаставляет меня думать, что, хотя порт ОС меняется при каждом запросе, каким-то образом эти запросы используют уже установленные физические соединения пула соединений.

Было бы замечательно, если бы кто-то еще мог запустить вышеупомянутый скрипт awk (просто используйте nawk наSolaris) в других средах приложений, использующих пул соединений jdbc, просто для сравнения чисел.

Если честно, я наблюдаю то же поведение на во всех наших средах приложений и только что заметилэто на двух сайтах клиентов, которые управляются совершенно другим приложением адмINS и разработчики.

И, конечно, не исключено, что существует общая неправильная конфигурация.

==================

Обновления: 2011/02/28

Подробнее об одной из сред.

4 экземпляра WL (2 x узла)
15 источников данных

Конфигурация:

initial-capacity: 5
max-capacity:     varies, from 20 to 150
capacity-increment: varies, from 1 to 5
connection-reserve-timeout-seconds: 10
test-frequency-seconds: varies, from 120 to 240
inactive-connection-timeout-seconds: 0
seconds-to-trust-an-idle-pool-connection: 10

Информация ниже относится к одному из узлов (2 экземпляра WL):

SQL> select sysdate from dual;

SYSDATE
--------------------
28/FEB/2011 12:03:50


SQL> select
  username, machine, logon_time, count(1)
from
  v$session
where
  machine='node1'
group by
  username, machine, logon_time
order by
  1,2,3;    2    3    4    5    6    7    8    9   10

USERNAME   MACHINE    LOGON_TIME             COUNT(1)
---------- ---------- -------------------- ----------
C_USER       node1     26/FEB/2011 20:25:01          1
C_USER       node1     26/FEB/2011 20:25:19          3
C_USER       node1     26/FEB/2011 20:25:20          2
C_USER       node1     26/FEB/2011 22:45:32          1
C_USER       node1     26/FEB/2011 22:45:46          5
C_USER       node1     27/FEB/2011 10:39:42          1
C_USER       node1     28/FEB/2011 09:25:16          1
C_USER       node1     28/FEB/2011 10:01:05          1
C_USER       node1     28/FEB/2011 10:01:06          1
C_USER       node1     28/FEB/2011 10:23:32          1
C_USER       node1     28/FEB/2011 10:23:33          6
C_USER       node1     28/FEB/2011 10:23:34          3
C_USER       node1     28/FEB/2011 10:36:09          1
C_USER       node1     28/FEB/2011 10:46:21          1
C_USER       node1     28/FEB/2011 11:00:17          1
C_USER       node1     28/FEB/2011 11:00:18          3
C_USER       node1     28/FEB/2011 11:16:26          2
C_USER       node1     28/FEB/2011 11:24:07          1
C_USER       node1     28/FEB/2011 11:24:08          1
C_USER       node1     28/FEB/2011 11:30:32          4
C_USER       node1     28/FEB/2011 11:30:33          1
C_USER       node1     28/FEB/2011 11:43:10          5
C_USER       node1     28/FEB/2011 11:50:36          9
C_USER       node1     28/FEB/2011 11:50:37          1
C_USER       node1     28/FEB/2011 11:54:16          2
C_USER       node1     28/FEB/2011 11:54:17          2
C_USER       node1     28/FEB/2011 12:01:52          2
C_USER       node1     28/FEB/2011 12:01:54          1
C_USER       node1     28/FEB/2011 12:01:55          4
S_USER       node1     26/FEB/2011 20:25:21          1
S_USER       node1     26/FEB/2011 22:45:47          1
W_USER       node1     23/FEB/2011 07:03:33          1
W_USER       node1     26/FEB/2011 20:25:05          1
W_USER       node1     26/FEB/2011 20:25:07          5
W_USER       node1     26/FEB/2011 20:25:15          3
W_USER       node1     26/FEB/2011 20:25:16          7
W_USER       node1     26/FEB/2011 20:25:17          1
W_USER       node1     26/FEB/2011 20:25:18          7
W_USER       node1     26/FEB/2011 20:25:19          3
W_USER       node1     26/FEB/2011 22:45:35          1
W_USER       node1     26/FEB/2011 22:45:37          4
W_USER       node1     26/FEB/2011 22:45:38          5
W_USER       node1     26/FEB/2011 22:45:42          5
W_USER       node1     26/FEB/2011 22:45:43          5
W_USER       node1     26/FEB/2011 22:45:44          3
W_USER       node1     26/FEB/2011 22:45:45          7
W_USER       node1     26/FEB/2011 22:45:46          1
W_USER       node1     27/FEB/2011 16:51:48          4

48 rows selected.

$ date
Mon Feb 28 12:19:35 CET 2011
$ tail -5000 listener_<snipped>.log | nawk 'END {
    for (i in count)
  if (count[i] > 10)
    print i, count[i]
}
  /__jdbc__.*HOST=<snipped>/ {
    sub(/:[^:]*$/, x, $2)
    count[$2]++
  }'| sort
07:29 13
08:57 13
09:09 18
09:24 18
09:29 27
09:32 13
09:37 17
09:51 12
10:01 13
10:06 27
10:12 17
10:19 13
10:20 12
10:22 17
10:23 16
10:35 17
11:00 13
11:21 18
11:24 17
11:38 13
11:43 32
11:50 13
11:54 23
12:01 15
12:05 17
12:10 28
12:17 18

mathewbutler · Answer 1 · 27 февраля 2011

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

Источник данных определяет пул соединений и поведение с точки зрения изменения размера и т. Д.

Я считаю, что параметры, используемые в определении источника данных, являются собственностью, поэтому обращайтесь к документации для JDBC.может понадобиться провайдер - это, скорее всего, Oracle, и он будет охватывать комплект документации Weblogic.

Надеюсь, это поможет.

Свяжите соединения JDBC с содержимым файла журнала прослушивателя Oracle

Обновления: 2011/02/28

Пожалуйста, войдите или зарегистрируйтесь чтобы ответить на этот вопрос.

1 Ответ

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

Свяжите соединения JDBC с содержимым файла журнала прослушивателя Oracle

Обновления: 2011/02/28

Пожалуйста, войдите или зарегистрируйтесь чтобы ответить на этот вопрос.

1 Ответ

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

Нет похожих вопросов