kadmin get * is SLOW

classic Classic list List threaded Threaded
27 messages Options
12
Reply | Threaded
Open this post in threaded view
|

kadmin get * is SLOW

Harald Barth-2

If anyone has pointers to why

$ kadmin get -s -o principal,mod_time \*

is slooooow (even on localhost), any pointers or solutions are very
appreciated. And with slow I mean approx 6 principals per second or
that a 128 bytes message from kadmin to kadmind needs approx 0.1 sec
and the return messages (253 bytes) needs as well approx 0.1 sec.

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Paul Robert Marino
I'm not sure why that might be happening mine is way faster than that.
what version of Heimdal are you using and on what OS?

On Mon, Jan 19, 2015 at 9:01 AM, Harald Barth <[hidden email]> wrote:

>
> If anyone has pointers to why
>
> $ kadmin get -s -o principal,mod_time \*
>
> is slooooow (even on localhost), any pointers or solutions are very
> appreciated. And with slow I mean approx 6 principals per second or
> that a 128 bytes message from kadmin to kadmind needs approx 0.1 sec
> and the return messages (253 bytes) needs as well approx 0.1 sec.
>
> Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2

> I'm not sure why that might be happening mine is way faster than that.
> what version of Heimdal are you using and on what OS?

The versions are

1.5.tip on FreeBSD or Solaris for the kadmind

1.6.something on Ubuntu or 1.5.tip on FreeBSD for the kadmin

Btw, kadmin -l is a lot faster.

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Henry B Hotz
Didn’t Russ Allbery submit a patch related to that not too long ago?

On Jan 19, 2015, at 7:35 AM, Harald Barth <[hidden email]> wrote:

>
>> I'm not sure why that might be happening mine is way faster than that.
>> what version of Heimdal are you using and on what OS?
>
> The versions are
>
> 1.5.tip on FreeBSD or Solaris for the kadmind
>
> 1.6.something on Ubuntu or 1.5.tip on FreeBSD for the kadmin
>
> Btw, kadmin -l is a lot faster.
>
> Harald.

Personal email.  [hidden email]



Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Love Hörnquist Åstrand
In reply to this post by Harald Barth-2

> 19 jan. 2015 kl. 16:35 skrev Harald Barth <[hidden email]>:
>
>
>> I'm not sure why that might be happening mine is way faster than that.
>> what version of Heimdal are you using and on what OS?
>
> The versions are
>
> 1.5.tip on FreeBSD or Solaris for the kadmind
>
> 1.6.something on Ubuntu or 1.5.tip on FreeBSD for the kadmin
>
> Btw, kadmin -l is a lot faster.

* (i.e. globbing) is kind of crappy since first it download the full list of principal (the string) that matches the expression, and then perform the that operation on all entries in the list.

-l is of course a lot faster since all operations are performed locally.

Is is the client or server using a lot of CPU ?

Any way to now for sure what’s going wrong is to perform an instrumented built.

Love

Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2

> * (i.e. globbing) is kind of crappy since first it download the full list of principal (the string) that matches the expression, and then perform the that operation on all entries in the list.

The first download of the whole list is fast, it's the get operations that are slow.

> Is is the client or server using a lot of CPU ?

No and no. Barely noticable. Neither disk I/O. Looks like everything
is cached in RAM.

> Any way to now for sure what’s going wrong is to perform an instrumented built.

I have som more data from ktrace that indicates that some reads take a lot
of time. Could that be a "TCP thing" that the check for new data available
on the descriptor just only happens every 1/10 sec?! No, it does not take
1/10 sec to  transfer 128 bytes.

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2

Here is the dump I talked about. I think I removed enough data to
protect whatevever ;-)

Harald.

dump.txt.gz (1K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Jeffrey Hutzelman
In reply to this post by Harald Barth-2
On Tue, 2015-01-20 at 10:00 +0100, Harald Barth wrote:
> > * (i.e. globbing) is kind of crappy since first it download the full list of principal (the string) that matches the expression, and then perform the that operation on all entries in the list.
>
> The first download of the whole list is fast, it's the get operations that are slow.

This has been true for a very long time.  It's not limited to cases
involving wildcards; it's just more noticeable when you're waiting to
get lots of principals.  The protocol is such that data for each
principal has to be retrieved as a separate operation, with a separate
round trip and, depending on the database backend, separate locking.
The synchronous nature of the API means you have to wait for one request
to finish before you get a chance to send the next one.

As Love points out, -l is much faster, because the kadmin protocol
doesn't get involved.

-- Jeff


Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Nico Williams
On Tue, Jan 20, 2015 at 04:41:55PM -0500, Jeffrey Hutzelman wrote:
> This has been true for a very long time.  It's not limited to cases
> involving wildcards; [...]

Nor to the kadmin protocol.  This is a traditional problem in
filesystems as well, with "ls -l" needing to read the directory, then
stat every file in it, which ultimately leads to filesystem clients
preemptively calling an RPC that combines READDIR and GETATTR (which is
added precisely for this).

kadmin needs an RPC for this.  Mind you, presumably you're not
extracting principal keys in plaintext (because you lack permission
to)...  You'd not want mass key extraction...

Nico
--
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Russ Allbery-2
In reply to this post by Harald Barth-2
Harald Barth <[hidden email]> writes:

> The versions are

> 1.5.tip on FreeBSD or Solaris for the kadmind

> 1.6.something on Ubuntu or 1.5.tip on FreeBSD for the kadmin

> Btw, kadmin -l is a lot faster.

What happens at the network protocol level for a remote get * is pretty
nasty.  You're basically making separate protocol requests for every
single principal in the database.

There probably isn't going to be a way to make that fast without some sort
of bulk-get operation that does the wildcard resolution on the server side
and returns all the data as a single reply.  (In other words, pretty
significant protocol changes.)

--
Russ Allbery ([hidden email])              <http://www.eyrie.org/~eagle/>
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2
In reply to this post by Jeffrey Hutzelman

> This has been true for a very long time.  It's not limited to cases
> involving wildcards; it's just more noticeable when you're waiting to
> get lots of principals.

That has been my impression as well.

> The protocol is such that data for each
> principal has to be retrieved as a separate operation, with a separate
> round trip and, depending on the database backend, separate locking.

Yes.

> The synchronous nature of the API means you have to wait for one request
> to finish before you get a chance to send the next one.

Yes.

But still I think 0.2 sec is very slow per request.

Fact: If I run 3 in parallell, I get 3 times the throughput, so I
doubt that locking or the database backend is a problem. The times in
the kdump do not point to any syscall but the network reads taking
time, in spite of that the corresponding write has already happened
(so the data is "in transit" over the loopback interface). Could there
be a problem with the I/O scheduling of the socket?

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2
In reply to this post by Russ Allbery-2

Hi Russ!

> There probably isn't going to be a way to make that fast without some sort
> of bulk-get operation that does the wildcard resolution on the server side
> and returns all the data as a single reply.  (In other words, pretty
> significant protocol changes.)

I can already make it faster by running concurrent gets. But I still
think there is a basic problem somewhere in the time that a single
get takes to complete, because I really don't see a bottleneck
when running over loopback on a machine that has more RAM than
all data together and all CPUs < 1% busy.

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Russ Allbery-2
Harald Barth <[hidden email]> writes:

> Hi Russ!

>> There probably isn't going to be a way to make that fast without some
>> sort of bulk-get operation that does the wildcard resolution on the
>> server side and returns all the data as a single reply.  (In other
>> words, pretty significant protocol changes.)

> I can already make it faster by running concurrent gets.

Given the server-side locking strategy, you're going to get limited
traction from doing that, I believe.

> But I still think there is a basic problem somewhere in the time that a
> single get takes to complete, because I really don't see a bottleneck
> when running over loopback on a machine that has more RAM than all data
> together and all CPUs < 1% busy.

I'm pretty sure the bottleneck is round-trip latency in the kadmin
protocol.  That operation is ridiculously chatty, not pipelined, and
entirely serial.

--
Russ Allbery ([hidden email])              <http://www.eyrie.org/~eagle/>
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Russ Allbery-2
Russ Allbery <[hidden email]> writes:

> I'm pretty sure the bottleneck is round-trip latency in the kadmin
> protocol.  That operation is ridiculously chatty, not pipelined, and
> entirely serial.

Is the server grabbing new /dev/random data for every request?  If you're
running out of entropy, that could also explain the delays.  I vaguely
recall having that problem with kadmin-related stuff in the past.

Hm, but that would slow down all the kadmins, so parallelism wouldn't
help.

I know I've seen this problem before -- I switched a bunch of tooling to
use kadmin -l for exactly this reason -- but I can't remember for certain
what I convinced myself the problem was.

--
Russ Allbery ([hidden email])              <http://www.eyrie.org/~eagle/>
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2
In reply to this post by Russ Allbery-2
> I'm pretty sure the bottleneck is round-trip latency in the kadmin
> protocol.  That operation is ridiculously chatty, not pipelined, and
> entirely serial.

client->server 4 bytes length (=128)
client->server 128 bytes get question      
server->client 4 bytes length (=253)
server->client 254 bytes get answer

I have the follwoing dump (I am trying to make 2 columns here):

   client                                              server
----------------------------------------------------------------------------------------------------------
1  kadmin 20.703007 GIO   fd 4 wrote 128 bytes
2                                                      kadmind  20.703014 GIO   fd 0 read 4 bytes
3  kadmin 20.703017 RET   write 128/0x80
4                                                      kadmind  20.703028 RET   read 4
5  kadmin 20.703036 CALL  close(0x4)
6                                                      kadmind  20.703048 CALL  read(0,0x803021080,0x80)
7  kadmin 20.703051 RET   close 0
8  kadmin 20.703067 CALL  dup(0x3)
9  kadmin 20.703074 RET   dup 4
10 kadmin 20.703081 CALL  read(0x4,0x7fffffffd140,0x4)
11                                                     kadmind  20.802628 GIO   fd 0 read 128 bytes
12                                                     kadmind  20.802636 RET   read 128/0x80

I am trying to understand why the 128 bytes write which definitely was
in the kernel at timestamp 20.703036 (row 5) and which kadmind waited
for since timestamp 20.703048 did block almost 1/10 sec and not
produce any data before time 20.802628 (row 11).

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Jeffrey Altman-2
On 1/22/2015 4:14 AM, Harald Barth wrote:

>> I'm pretty sure the bottleneck is round-trip latency in the kadmin
>> protocol.  That operation is ridiculously chatty, not pipelined, and
>> entirely serial.
>
> client->server 4 bytes length (=128)
> client->server 128 bytes get question      
> server->client 4 bytes length (=253)
> server->client 254 bytes get answer
> [deleted text]
> I am trying to understand why the 128 bytes write which definitely was
> in the kernel at timestamp 20.703036 (row 5) and which kadmind waited
> for since timestamp 20.703048 did block almost 1/10 sec and not
> produce any data before time 20.802628 (row 11).
>
> Harald.

My guess is

  https://en.wikipedia.org/wiki/Nagle%27s_algorithm

Jeffrey Altman



smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Harald Barth-2

Thanks Chas, Jeff, I will look into the TCP_NODLEAY option.

Harald.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Mark Eichin-3
writev is worth a look too.
Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Jeffrey Hutzelman
In reply to this post by Jeffrey Altman-2
On Thu, 2015-01-22 at 11:49 -0500, Jeffrey Altman wrote:

> On 1/22/2015 4:14 AM, Harald Barth wrote:
> >> I'm pretty sure the bottleneck is round-trip latency in the kadmin
> >> protocol.  That operation is ridiculously chatty, not pipelined, and
> >> entirely serial.
> >
> > client->server 4 bytes length (=128)
> > client->server 128 bytes get question      
> > server->client 4 bytes length (=253)
> > server->client 254 bytes get answer
> > [deleted text]
> > I am trying to understand why the 128 bytes write which definitely was
> > in the kernel at timestamp 20.703036 (row 5) and which kadmind waited
> > for since timestamp 20.703048 did block almost 1/10 sec and not
> > produce any data before time 20.802628 (row 11).
> >
> > Harald.
>
>
> My guess is
>
>   https://en.wikipedia.org/wiki/Nagle%27s_algorithm

See, I thought that too, but I was going to see if I could take some
measurements to prove it, and maybe work up a trial patch, before saying
anything.  The problem is, I don't see why either the kadmin client or
server should be generating the odd pattern of successive small writes
required to cause a problem.

-- Jeff

Reply | Threaded
Open this post in threaded view
|

Re: kadmin get * is SLOW

Nico Williams
On Thu, Jan 22, 2015 at 03:58:52PM -0500, Jeffrey Hutzelman wrote:

> On Thu, 2015-01-22 at 11:49 -0500, Jeffrey Altman wrote:
> > On 1/22/2015 4:14 AM, Harald Barth wrote:
> > >> I'm pretty sure the bottleneck is round-trip latency in the kadmin
> > >> protocol.  That operation is ridiculously chatty, not pipelined, and
> > >> entirely serial.
> > >
> > > client->server 4 bytes length (=128)
> > > client->server 128 bytes get question      
> > > server->client 4 bytes length (=253)
> > > server->client 254 bytes get answer
> > > [deleted text]
> > > I am trying to understand why the 128 bytes write which definitely was
> > > in the kernel at timestamp 20.703036 (row 5) and which kadmind waited
> > > for since timestamp 20.703048 did block almost 1/10 sec and not
> > > produce any data before time 20.802628 (row 11).
> > >
> > > Harald.
> >
> >
> > My guess is
> >
> >   https://en.wikipedia.org/wiki/Nagle%27s_algorithm
>
> See, I thought that too, but I was going to see if I could take some
> measurements to prove it, and maybe work up a trial patch, before saying
> anything.  The problem is, I don't see why either the kadmin client or
> server should be generating the odd pattern of successive small writes
> required to cause a problem.

I think that's completely to be expected in general, even if not in this
case (haven't looked).  Particularly as we add more in-place + scatter/
gather crypto APIs.  We should make use of TCP_CORK where we can.

Nico
--
12