Speed difference between superuser and others

RT Users
#1

Hi,

I have a big performance problem here:

When I connect to my RT system with a superuser account, it’s fine.

When I connect with a normal privileged user, without groups or any
rights, It’s really slow (more than 3 minutes for Rt at a glance).

The curious thing is that 90% of the time is without database access and
without CPU load, just the fastcgi process waiting.

When I strace it, the main difference is that the non super user produce
a lot of lines like this:

time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
time(NULL) = 1184917363
write(4, “\2\303\0\0\6\0\0\0\0\0\21i\207\1\1\1\1\6\3^\210\3\2\200”…, 707) = 707
read(4, “\0\227\0\0\6\0\0\0\0\0\20\35\311\321F>\300\0\0\0\366\273”…, 2064) = 151
gettimeofday({1184917363, 602652}, NULL) = 0
write(4, “\0T\0\0\6\0\0\0\0\0\3^\211\2\200p\1\6\0\0\1\1\f\0\1\0\2”…, 84) = 84
read(4, “\0S\0\0\6\0\0\0\0\0\10\1\5\3\30\355,\0\1\6\0\0\0\0\4\1”…, 2064) = 83
gettimeofday({1184917363, 610756}, NULL) = 0
gettimeofday({1184917363, 611800}, NULL) = 0
write(4, “\3\21\0\0\6\0\0\0\0\0\21i\212\1\1\1\1\6\3^\213\3\2\200”…, 785) = 785
read(4, “\0\227\0\0\6\0\0\0\0\0\20\35\2261]\v\300\0\0\0\366\234”…, 2064) = 151
gettimeofday({1184917363, 619729}, NULL) = 0
write(4, “\0T\0\0\6\0\0\0\0\0\3^\214\2\200p\1\6\0\0\1\1\f\0\1\0\2”…, 84) = 84
read(4, “\0S\0\0\6\0\0\0\0\0\10\1\5\3\30\3558\0\1\6\0\0\0\0\4\1”…, 2064) = 83
gettimeofday({1184917365, 57412}, NULL) = 0
gettimeofday({1184917365, 58479}, NULL) = 0
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
time(NULL) = 1184917365
write(4, “\2\303\0\0\6\0\0\0\0\0\21i\215\1\1\1\1\6\3^\216\3\2\200”…, 707) = 707
read(4, “\0\227\0\0\6\0\0\0\0\0\20\35\311\321F>\300\0\0\0\366\273”…, 2064) = 151
gettimeofday({1184917365, 81413}, NULL) = 0
write(4, “\0T\0\0\6\0\0\0\0\0\3^\217\2\200p\1\6\0\0\1\1\f\0\1\0\2”…, 84) = 84
read(4, “\0S\0\0\6\0\0\0\0\0\10\1\5\3\30\3558\0\1\6\0\0\0\0\4\1”…, 2064) = 83
gettimeofday({1184917365, 89500}, NULL) = 0
gettimeofday({1184917365, 90543}, NULL) = 0
write(4, “\3\21\0\0\6\0\0\0\0\0\21i\220\1\1\1\1\6\3^\221\3\2\200”…, 785) = 785

…

Also, but this is not a difference between the two tests, I see a lot of lines like this:

connect(13, {sa_family=AF_FILE, path=“/dev/log”}, 110) = -1 EPROTOTYPE (Protocol wrong type for socket)
close(13) = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 13
ioctl(13, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbff19b98) = -1 EINVAL (Invalid argument)
_llseek(13, 0, 0xbff19bd0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
ioctl(13, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbff19b98) = -1 EINVAL (Invalid argument)
_llseek(13, 0, 0xbff19bd0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fcntl64(13, F_SETFD, FD_CLOEXEC) = 0

and:

$ ls -l /dev/log
srw-rw-rw- 1 root root 0 Oct 3 2006 /dev/log

seems ok.

It’s running under RedHat ES4 on a vmware server, and connected to an external Oracle database.

Thanks for any help :slight_smile:

Emmanuel Lacour ------------------------------------ Easter-eggs
44-46 rue de l’Ouest - 75014 Paris - France - Métro Gaité
Phone: +33 (0) 1 43 35 00 37 - Fax: +33 (0) 1 41 35 00 76
mailto:elacour@easter-eggs.com - http://www.easter-eggs.com

#2

Hi,

I have a big performance problem here:

When I connect to my RT system with a superuser account, it’s fine.

When I connect with a normal privileged user, without groups or any
rights, It’s really slow (more than 3 minutes for Rt at a glance).

What RT and what SearchBuilder? The loop you show suggest that it’s
an ancient version of DBIx::SearchBuilder with a big caching problem.

Best,
Jesse

PGP.sig (186 Bytes)

#3

What RT and what SearchBuilder? The loop you show suggest that it’s
an ancient version of DBIx::SearchBuilder with a big caching problem.

Comming back from vacations … :wink:

I’m using version 1.43 (the one I found packaged for RH :(), I didn’t
clearly identify your caching problem in the change file from this
release, is 1.43 affected ?

1.49 is packaged at
http://dag.wieers.com/rpm/packages/perl-DBIx-SearchBuilder/ since
yesterday, so I will try it :wink:

Thanks for your help :slight_smile:

Emmanuel Lacour ------------------------------------ Easter-eggs
44-46 rue de l’Ouest - 75014 Paris - France - Métro Gaité
Phone: +33 (0) 1 43 35 00 37 - Fax: +33 (0) 1 41 35 00 76
mailto:elacour@easter-eggs.com - http://www.easter-eggs.com

#4

1.49 is packaged at
http://dag.wieers.com/rpm/packages/perl-DBIx-SearchBuilder/ since
yesterday, so I will try it :wink:

I tested this last version without any performance improvement :frowning:

Rt is 3.6.3, with a backport of QueueSummary from 3.6.4

Emmanuel Lacour ------------------------------------ Easter-eggs
44-46 rue de l’Ouest - 75014 Paris - France - Métro Gaité
Phone: +33 (0) 1 43 35 00 37 - Fax: +33 (0) 1 41 35 00 76
mailto:elacour@easter-eggs.com - http://www.easter-eggs.com

#5

1.49 is packaged at
http://dag.wieers.com/rpm/packages/perl-DBIx-SearchBuilder/ since
yesterday, so I will try it :wink:

I tested this last version without any performance improvement :frowning:

Rt is 3.6.3, with a backport of QueueSummary from 3.6.4

I found that the 90% of the time of the first RT acces with a non
superuser user is for checking ACLs of queues. It does about 800 SQL
requests for RT at a Glance (I have 189 queues, displayed three times
on RT at a Glance default page).

As the result, the first access take 5 minutes to display this page.

A second access use the session RT cache and take only 20 seconds (which
remains slow :().

We are using an oracle database (9.2.0.7.0). This database is on a
dedicated server with Gigabit connexion to the RT server.

We do not see any problem with databse performances, could this speed
problem be related to the fact that the database is on a différent
server (the database server as a ping of about 2ms from the RT server).

Thanks for any hints on solving this performance problem :frowning:

Emmanuel Lacour ------------------------------------ Easter-eggs
44-46 rue de l’Ouest - 75014 Paris - France - Métro Gaité
Phone: +33 (0) 1 43 35 00 37 - Fax: +33 (0) 1 41 35 00 76
mailto:elacour@easter-eggs.com - http://www.easter-eggs.com

#6

1.49 is packaged at
http://dag.wieers.com/rpm/packages/perl-DBIx-SearchBuilder/ since
yesterday, so I will try it :wink:

I tested this last version without any performance improvement :frowning:

Rt is 3.6.3, with a backport of QueueSummary from 3.6.4

I found that the 90% of the time of the first RT acces with a non
superuser user is for checking ACLs of queues. It does about 800 SQL
requests for RT at a Glance (I have 189 queues, displayed three times
on RT at a Glance default page).

As the result, the first access take 5 minutes to display this page.

A second access use the session RT cache and take only 20 seconds (which
remains slow :().

We are using an oracle database (9.2.0.7.0). This database is on a
dedicated server with Gigabit connexion to the RT server.

We do not see any problem with databse performances, could this speed
problem be related to the fact that the database is on a diff??rent
server (the database server as a ping of about 2ms from the RT server).

Thanks for any hints on solving this performance problem :frowning:

–
Emmanuel Lacour ------------------------------------ Easter-eggs
44-46 rue de l’Ouest - 75014 Paris - France - M??tro Gait??
Phone: +33 (0) 1 43 35 00 37 - Fax: +33 (0) 1 41 35 00 76
mailto:elacour@easter-eggs.com - http://www.easter-eggs.com

Emmanuel,

That does seem a little bit excessive. 800 SQL queries in 5 minutes
is about 1/3 second per query which seems slow to me. You may want to
turn on query logging/timing and try to analyze them to find the
bottleneck. We only have 80 queues, but the initial load takes about
2.5 seconds the first time and 2 seconds thereafter. Good luck with
your performance tuning.

Regards,
Ken Marshall

#7

That does seem a little bit excessive. 800 SQL queries in 5 minutes
is about 1/3 second per query which seems slow to me. You may want to
turn on query logging/timing and try to analyze them to find the
bottleneck. We only have 80 queues, but the initial load takes about
2.5 seconds the first time and 2 seconds thereafter. Good luck with
your performance tuning.

Thanks for your answer, I think also that it is a database issue, I’m
going to look at it in depth :wink:

Emmanuel Lacour

#8

That does seem a little bit excessive. 800 SQL queries in 5 minutes
is about 1/3 second per query which seems slow to me. You may want to
turn on query logging/timing and try to analyze them to find the
bottleneck. We only have 80 queues, but the initial load takes about
2.5 seconds the first time and 2 seconds thereafter. Good luck with
your performance tuning.

Thanks for your answer, I think also that it is a database issue, I’m
going to look at it in depth :wink:

Fixed, on this Oracle 9.2.0.7.0, we had to create the following index
(don’t know why the DisGrouMem index is not used :():

CREATE INDEX GemDisMem ON CachedGroupMembers
(Disabled, MemberId)
LOGGING
TABLESPACE USERS
PCTFREE 10
INITRANS 2
MAXTRANS 255
STORAGE (
INITIAL 64K
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
BUFFER_POOL DEFAULT
)
NOPARALLEL;

with this, it’s working fine :slight_smile:

Note: I tested on a 10g database, the speed is ok without this index…

Emmanuel Lacour