Re: [Freeipa-devel] slow response
On Tue, Sep 11, 2012 at 9:17 PM, Stephen Ingram sbing...@gmail.com wrote: On Tue, Sep 11, 2012 at 7:31 PM, Rob Crittenden rcrit...@redhat.com wrote: Stephen Ingram wrote: On Tue, Aug 7, 2012 at 1:53 PM, Simo Sorce s...@redhat.com wrote: On Tue, 2012-08-07 at 13:30 -0700, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 1:04 PM, Simo Sorce s...@redhat.com wrote: Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 As I'm thinking this might also solve my IPA large memory usage issue, I've been following this bug and see there is now a patch for it. I also see it is in QA along with several other IPA-related (and non-IPA-related) Kerberos fixes. I thought at some point an errata release would happen during the RHEL 6.3 time-frame, but as I'm not too familiar with how this works, so I'm not sure. Is this a possibility, or are these being held back for some reason like additional QA time? Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Fri, Oct 05, 2012 at 12:02:52PM -0700, Stephen Ingram wrote: As I'm thinking this might also solve my IPA large memory usage issue, I've been following this bug and see there is now a patch for it. I also see it is in QA along with several other IPA-related (and non-IPA-related) Kerberos fixes. That group is currently slated for a later update. I thought at some point an errata release would happen during the RHEL 6.3 time-frame, but as I'm not too familiar with how this works, so I'm not sure. Is this a possibility, or are these being held back for some reason like additional QA time? The isolated fix was pushed as RHBA-2012:1294. Cheers, Nalin ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Tue, Aug 7, 2012 at 1:53 PM, Simo Sorce s...@redhat.com wrote: On Tue, 2012-08-07 at 13:30 -0700, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 1:04 PM, Simo Sorce s...@redhat.com wrote: Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 I could see this BZ for a couple of days, but now it says that I must log in to an account first with the appropriate permissions. Has this been moved or something? Steve Sorry Stpehen we have a stupid bot that sometimes decides to flag bugs as internal for reasons I do not understand, I removed the flag, you should be able to see it again now. This must have happened again as I can no longer see the bug. This must be a tough one as there seems to still be no update? Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
Stephen Ingram wrote: On Tue, Aug 7, 2012 at 1:53 PM, Simo Sorce s...@redhat.com wrote: On Tue, 2012-08-07 at 13:30 -0700, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 1:04 PM, Simo Sorce s...@redhat.com wrote: Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 I could see this BZ for a couple of days, but now it says that I must log in to an account first with the appropriate permissions. Has this been moved or something? Steve Sorry Stpehen we have a stupid bot that sometimes decides to flag bugs as internal for reasons I do not understand, I removed the flag, you should be able to see it again now. This must have happened again as I can no longer see the bug. This must be a tough one as there seems to still be no update? Hmm, I can see it without logging into BZ. The short summary is that Nalin has a patch for it as of yesterday. rob ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Tue, Sep 11, 2012 at 7:31 PM, Rob Crittenden rcrit...@redhat.com wrote: Stephen Ingram wrote: On Tue, Aug 7, 2012 at 1:53 PM, Simo Sorce s...@redhat.com wrote: On Tue, 2012-08-07 at 13:30 -0700, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 1:04 PM, Simo Sorce s...@redhat.com wrote: Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 I could see this BZ for a couple of days, but now it says that I must log in to an account first with the appropriate permissions. Has this been moved or something? Steve Sorry Stpehen we have a stupid bot that sometimes decides to flag bugs as internal for reasons I do not understand, I removed the flag, you should be able to see it again now. This must have happened again as I can no longer see the bug. This must be a tough one as there seems to still be no update? Hmm, I can see it without logging into BZ. The short summary is that Nalin has a patch for it as of yesterday. I can see the bug again now too. Strange. Thanks for the update too. Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Thu, Aug 2, 2012 at 1:04 PM, Simo Sorce s...@redhat.com wrote: Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 I could see this BZ for a couple of days, but now it says that I must log in to an account first with the appropriate permissions. Has this been moved or something? Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Tue, 2012-08-07 at 13:30 -0700, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 1:04 PM, Simo Sorce s...@redhat.com wrote: Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 I could see this BZ for a couple of days, but now it says that I must log in to an account first with the appropriate permissions. Has this been moved or something? Steve Sorry Stpehen we have a stupid bot that sometimes decides to flag bugs as internal for reasons I do not understand, I removed the flag, you should be able to see it again now. Simo. -- Simo Sorce * Red Hat, Inc * New York ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 08/02/2012 11:17 AM, Stephen Ingram wrote: On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorces...@redhat.com wrote: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacekpspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. I've done this. It looks like this delay has been uncovered already though? I can still send you the dump privately if you think it would help. We have a somewhat reproducible test case - see https://bugzilla.redhat.com/show_bug.cgi?id=845125 - note that the problem only seems to occur on RHEL 6.3 with the latest Z-stream packages. Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Thu, 2012-08-02 at 10:17 -0700, Stephen Ingram wrote: On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorce s...@redhat.com wrote: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacek pspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. I've done this. It looks like this delay has been uncovered already though? I can still send you the dump privately if you think it would help. I think we reproduced it, can you confirm you are also running on RHEL ? So far it seem the only platfrom we can reproduce is RHEL 6.3 Simo. -- Simo Sorce * Red Hat, Inc * New York ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Thu, Aug 2, 2012 at 10:23 AM, Simo Sorce s...@redhat.com wrote: On Thu, 2012-08-02 at 10:17 -0700, Stephen Ingram wrote: On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorce s...@redhat.com wrote: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacek pspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. I've done this. It looks like this delay has been uncovered already though? I can still send you the dump privately if you think it would help. I think we reproduced it, can you confirm you are also running on RHEL ? So far it seem the only platfrom we can reproduce is RHEL 6.3 Yes, I'm running RHEL 6.3. I just ran the command in the BZ and it takes 1.542s for me. What are Z-stream packages? Is this new for 389ds? Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 08/02/2012 11:29 AM, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 10:23 AM, Simo Sorces...@redhat.com wrote: On Thu, 2012-08-02 at 10:17 -0700, Stephen Ingram wrote: On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorces...@redhat.com wrote: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacekpspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. I've done this. It looks like this delay has been uncovered already though? I can still send you the dump privately if you think it would help. I think we reproduced it, can you confirm you are also running on RHEL ? So far it seem the only platfrom we can reproduce is RHEL 6.3 Yes, I'm running RHEL 6.3. I just ran the command in the BZ and it takes 1.542s for me. What are Z-stream packages? They are packages delivered between minor RHEL releases e.g. between RHEL 6.3 and RHEL 6.4 - the 389-ds-base package released with RHEL 6.3 was 389-ds-base-1.2.10.2-15.el6 - since RHEL 6.3, we released some bugfix packages, and the latest is now 389-ds-base-1.2.10.2-20.el6_3 - note the _3 at the end - this means it is a bugfix release for RHEL 6.3 - Z-stream is just Red Hat terminology for a package released between minor RHEL releases - the Z stands for the Z in the versioning scheme X.Y.Z Is this new for 389ds? Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Thu, Aug 2, 2012 at 10:33 AM, Rich Megginson rmegg...@redhat.com wrote: On 08/02/2012 11:29 AM, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 10:23 AM, Simo Sorces...@redhat.com wrote: On Thu, 2012-08-02 at 10:17 -0700, Stephen Ingram wrote: On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorces...@redhat.com wrote: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacekpspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. I've done this. It looks like this delay has been uncovered already though? I can still send you the dump privately if you think it would help. I think we reproduced it, can you confirm you are also running on RHEL ? So far it seem the only platfrom we can reproduce is RHEL 6.3 Yes, I'm running RHEL 6.3. I just ran the command in the BZ and it takes 1.542s for me. What are Z-stream packages? They are packages delivered between minor RHEL releases e.g. between RHEL 6.3 and RHEL 6.4 - the 389-ds-base package released with RHEL 6.3 was 389-ds-base-1.2.10.2-15.el6 - since RHEL 6.3, we released some bugfix packages, and the latest is now 389-ds-base-1.2.10.2-20.el6_3 - note the _3 at the end - this means it is a bugfix release for RHEL 6.3 - Z-stream is just Red Hat terminology for a package released between minor RHEL releases - the Z stands for the Z in the versioning scheme X.Y.Z Got it. We are using those packages now. Although this might or might not be the cause of the slow Web UI, the Web UI has been slow since the initial 6.3 release. If this 389 slowness was only introduced in the Z-stream 389ds, then it is likely not, or not the only, cause of the Web UI slowness. Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 08/02/2012 11:56 AM, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 10:33 AM, Rich Megginsonrmegg...@redhat.com wrote: On 08/02/2012 11:29 AM, Stephen Ingram wrote: On Thu, Aug 2, 2012 at 10:23 AM, Simo Sorces...@redhat.com wrote: On Thu, 2012-08-02 at 10:17 -0700, Stephen Ingram wrote: On Wed, Aug 1, 2012 at 7:35 AM, Simo Sorces...@redhat.com wrote: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacekpspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. I've done this. It looks like this delay has been uncovered already though? I can still send you the dump privately if you think it would help. I think we reproduced it, can you confirm you are also running on RHEL ? So far it seem the only platfrom we can reproduce is RHEL 6.3 Yes, I'm running RHEL 6.3. I just ran the command in the BZ and it takes 1.542s for me. What are Z-stream packages? They are packages delivered between minor RHEL releases e.g. between RHEL 6.3 and RHEL 6.4 - the 389-ds-base package released with RHEL 6.3 was 389-ds-base-1.2.10.2-15.el6 - since RHEL 6.3, we released some bugfix packages, and the latest is now 389-ds-base-1.2.10.2-20.el6_3 - note the _3 at the end - this means it is a bugfix release for RHEL 6.3 - Z-stream is just Red Hat terminology for a package released between minor RHEL releases - the Z stands for the Z in the versioning scheme X.Y.Z Got it. We are using those packages now. Although this might or might not be the cause of the slow Web UI, the Web UI has been slow since the initial 6.3 release. If this 389 slowness was only introduced in the Z-stream 389ds, then it is likely not, or not the only, cause of the Web UI slowness. The 389 slowness was not introduced in the Z-stream package (-20.el6_3) - the slowness is present in the RHEL 6.3.0 package (-15.el6) Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
Quick heads up in this thread, apparently we have isolated the issue to libkrb5 and its selinux integration. I have made the whole delay go away by disabling selinux entirely (which makes libkrb5 stop trying to do some selinux related operations). We will be working on a fix to have libkrb5 not cause this delay (F17 doesn't have it). You can follow progress on this bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=845125 Simo. -- Simo Sorce * Red Hat, Inc * New York ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
El mié, 01-08-2012 a las 10:35 -0400, Simo Sorce escribió: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacek pspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Hi, I experience the same delay in SASL authentication. The number I posted on freeipa-users, show a 1-2 second delay with SASL authentication: # time ldapsearch -x uid=bdteg01662 dn # extended LDIF # # LDAPv3 # base dc=xxx,dc=gob,dc=ve (default) with scope subtree # filter: uid=bdteg01662 # requesting: dn # # bdteg01662, users, accounts, xxx.gob.ve dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve # search result search: 2 result: 0 Success # numResponses: 2 # numEntries: 1 real0m0.006s user0m0.001s sys 0m0.003s # time ldapsearch -Y GSSAPI uid=bdteg01662 dn SASL/GSSAPI authentication started SASL username: ad...@xxx.gob.ve SASL SSF: 56 SASL data security layer installed. # extended LDIF # # LDAPv3 # base dc=xxx,dc=gob,dc=ve (default) with scope subtree # filter: uid=bdteg01662 # requesting: dn # # bdteg01662, users, accounts, xxx.gob.ve dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve # search result search: 4 result: 0 Success # numResponses: 2 # numEntries: 1 real0m2.344s user0m0.007s sys 0m0.005s Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. Simo. -- Loris Santamaria linux user #70506 xmpp:lo...@lgs.com.ve Links Global Services, C.A.http://www.lgs.com.ve Tel: 0286 952.06.87 Cel: 0414 095.00.10 sip:1...@lgs.com.ve If I'd asked my customers what they wanted, they'd have said a faster horse - Henry Ford smime.p7s Description: S/MIME cryptographic signature ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 08/01/2012 09:20 AM, Loris Santamaria wrote: El mié, 01-08-2012 a las 10:35 -0400, Simo Sorce escribió: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacekpspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Hi, I experience the same delay in SASL authentication. The number I posted on freeipa-users, show a 1-2 second delay with SASL authentication: # time ldapsearch -x uid=bdteg01662 dn # extended LDIF # # LDAPv3 # basedc=xxx,dc=gob,dc=ve (default) with scope subtree # filter: uid=bdteg01662 # requesting: dn # # bdteg01662, users, accounts, xxx.gob.ve dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve # search result search: 2 result: 0 Success # numResponses: 2 # numEntries: 1 real0m0.006s user0m0.001s sys 0m0.003s # time ldapsearch -Y GSSAPI uid=bdteg01662 dn SASL/GSSAPI authentication started SASL username: ad...@xxx.gob.ve SASL SSF: 56 SASL data security layer installed. # extended LDIF # # LDAPv3 # basedc=xxx,dc=gob,dc=ve (default) with scope subtree # filter: uid=bdteg01662 # requesting: dn # # bdteg01662, users, accounts, xxx.gob.ve dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve # search result search: 4 result: 0 Success # numResponses: 2 # numEntries: 1 real0m2.344s user0m0.007s sys 0m0.005s Can you post excerpts from your 389 access log showing the sequence of operations for this connection, bind and search? Can you test connecting to the ldap server using ldapsearch -Y GSSAPI (you need a kerberos ticket) and telling me if you experience any delay ? If you could run a bunch of searches in a loop and take a wireshark trace that may help analyzing the timings and seeing if there is a correlation. Simo. ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 08/01/2012 01:34 PM, Loris Santamaria wrote: El mié, 01-08-2012 a las 09:58 -0600, Rich Megginson escribió: On 08/01/2012 09:20 AM, Loris Santamaria wrote: El mié, 01-08-2012 a las 10:35 -0400, Simo Sorce escribió: On Tue, 2012-07-31 at 08:49 -0700, Stephen Ingram wrote: On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacekpspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Stephen, another user sent me a wireshark trace for a similar performance issue. So far I see a pause when doing the first leg of a SASL authentication. This may well explain also your issue. Hi, I experience the same delay in SASL authentication. The number I posted on freeipa-users, show a 1-2 second delay with SASL authentication: # time ldapsearch -x uid=bdteg01662 dn # extended LDIF # # LDAPv3 # basedc=xxx,dc=gob,dc=ve (default) with scope subtree # filter: uid=bdteg01662 # requesting: dn # # bdteg01662, users, accounts, xxx.gob.ve dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve # search result search: 2 result: 0 Success # numResponses: 2 # numEntries: 1 real0m0.006s user0m0.001s sys 0m0.003s # time ldapsearch -Y GSSAPI uid=bdteg01662 dn SASL/GSSAPI authentication started SASL username: ad...@xxx.gob.ve SASL SSF: 56 SASL data security layer installed. # extended LDIF # # LDAPv3 # basedc=xxx,dc=gob,dc=ve (default) with scope subtree # filter: uid=bdteg01662 # requesting: dn # # bdteg01662, users, accounts, xxx.gob.ve dn: uid=bdteg01662,cn=users,cn=accounts,dc=xxx,dc=gob,dc=ve # search result search: 4 result: 0 Success # numResponses: 2 # numEntries: 1 real0m2.344s user0m0.007s sys 0m0.005s Can you post excerpts from your 389 access log showing the sequence of operations for this connection, bind and search? Here they are: [01/Aug/2012:10:39:40 -041800] conn=33 fd=70 slot=70 connection from 172.18.32.246 to 172.18.32.246 [01/Aug/2012:10:39:40 -041800] conn=33 op=0 BIND dn= method=sasl version=3 mech=GSSAPI [01/Aug/2012:10:39:42 -041800] conn=33 op=0 RESULT err=14 tag=97 nentries=0 etime=2, SASL bind in progress Yep, this is it - this should not be taking 2 seconds. I'd like to see what internal operations are going on in this time. Try this - follow the directions at http://port389.org/wiki/FAQ#Troubleshooting but for the access log, to turn on Heavy trace output debugging: dn: cn=config changetype: modify replace: nsslapd-accesslog-level nsslapd-accesslog-level: 4 Then turn the access log level back to the default (256) after reproducing the problem. We should then be able to see the sequence of internal operations triggered by the BIND dn= method=sasl version=3 mech=GSSAPI [01/Aug/2012:10:39:42 -041800] conn=33 op=1 BIND dn= method=sasl version=3 mech=GSSAPI [01/Aug/2012:10:39:42 -041800] conn=33 op=1 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress [01/Aug/2012:10:39:42 -041800] conn=33 op=2 BIND dn= method=sasl
Re: [Freeipa-devel] slow response
On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? Is SSSD running on problematic server? Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) === End of wild speculations === Petr^2 Spacek ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Tue, Jul 31, 2012 at 1:39 AM, Petr Spacek pspa...@redhat.com wrote: On 07/31/2012 12:27 AM, John Dennis wrote: What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). A note regarding python-krbV: I used python-krbV extensively in my thesis for KDC stress test. Python-krbV can obtain several thousands of TGTs per second (even with ccache in a file). AFAIK VFS calls are not done synchronously. But others parts of python-krbV were left uncovered, so it can contain some surprises. === Wild speculation follows === 1.5 second is incredibly long time, it sounds like some kind of timeout. Krb5 libs have usual timeout = 1 second per request. Are all KDCs in /etc/krb5.conf alive and reachable? In this case, as I'm referring to the extreme slowness of the Web UI, the KDC is on the same system (the ipa server) that is making the request, correct? Is SSSD running on problematic server? Yes. Again, I'm guessing the problematic server is the IPA server itself. Is proper KDC selected by SSSD KDC auto-locator plugin? (See /var/lib/sss/pubconf/) Yes, I checked that file and it is the IP address of the IPA server on the same server. Perhaps should this be 127.0.0.1 instead? I also have checked the resolv.conf file, and indeed the IP points to the IPA server itself (same machine) as expected. Both forward and reverse DNS work. I'm not really sure what else could be setup incorrectly to cause any KDC slowness. Due to the extreme UI slowness issue, I have not created any replicas so this system is it. I'm not so sure I would be able to see the 1.5 s delay if it weren't compounded by the overall slowness of the Web UI, however, the KDC seems to perform well for other systems in the realm. I'm certainly not taxing it with a huge load, but tickets seem to be issued without delay. Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 07/30/2012 11:30 AM, Stephen Ingram wrote:
On Wed, Jul 25, 2012 at 11:18 PM, Stephen Ingram sbing...@gmail.com wrote:
On Wed, Jul 25, 2012 at 4:31 AM, John Dennis jden...@redhat.com wrote:
On 07/25/2012 02:59 AM, Stephen Ingram wrote:
Seeing python2.7, I'm guessing these patches were against Fedora.
Since I couldn't get them to apply against RH 6.3 I applied them by
hand. I couldn't get the WebUI to load after applying the patches. I'm
not sure of the code that caused the problem, but I did see mention of
global name datetime not being defined. You wouldn't happen to have
patches for RH 6.3?
Sorry, I thought you had a F17 install. It should be easy to fix the
datetime issue, just add this add the top of the file:
import time, datetime
If that simple fix doesn't work then let me know the version you've got and
I'll make up a new patch against that version.
Yes, please send a patch for 2.20 with RH 6.3. The import time,
datetime did not address all of the errors.
Not sure if you missed this one or not, but, yes, I do need a patch
for 2.20 on RH 6.3. I added datetime, but there were still other
errors that I couldn't resolve.
Sorry, I did see it but I was busy with other things. You can try the
attached patch. However you need to have a clean set of files to patch
against. The patch command I suggested included the -b option and would
have created backup files of the original file with a .orig suffix.
These are the files the patch touches.
ipalib/session.py
ipaserver/plugins/ldap2.py
ipaserver/rpcserver.py
Find their .orig version and cp it back to the original filename. Then
you can try applying the patch again.
Caveat: I did not test this against 2.20, I just manually made the same
set of changes and generated a patch, it's possible in my hurry I made a
mistake you may need to tweak,
--
John Dennis jden...@redhat.com
Looking to carve out IT costs?
www.redhat.com/carveoutcosts/
diff --git a/ipalib/session.py b/ipalib/session.py
index 4b783bb..8eb9105 100644
--- a/ipalib/session.py
+++ b/ipalib/session.py
@@ -23,6 +23,7 @@ import errors
import os
import re
import time
+import datetime
from text import _
from ipapython.ipa_log_manager import *
from ipalib import api, errors
@@ -628,9 +629,9 @@ mod_auth_kerb. Everything else remains the same.
default_max_session_duration = 60*60 # number of seconds
-ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S' # FIXME jrd, this should be defined elsewhere
+ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S.%f' # FIXME jrd, this should be defined elsewhere
def fmt_time(timestamp):
-return time.strftime(ISO8601_DATETIME_FMT, time.localtime(timestamp))
+return datetime.fromtimestamp(timestamp).strftime(ISO8601_DATETIME_FMT)
#---
diff --git a/ipaserver/plugins/ldap2.py b/ipaserver/plugins/ldap2.py
index ddef8df..2d7447d 100644
--- a/ipaserver/plugins/ldap2.py
+++ b/ipaserver/plugins/ldap2.py
@@ -733,6 +733,7 @@ class ldap2(CrudBackend, Encoder):
attrs_list = list(set(attrs_list))
# pass arguments to python-ldap
+start_time = time.time()
try:
id = self.conn.search_ext(
base_dn, scope, filter, attrs_list, timeout=time_limit,
@@ -751,6 +752,9 @@ class ldap2(CrudBackend, Encoder):
except _ldap.LDAPError, e:
_handle_errors(e)
+end_time = time.time()
+root_logger.debug('ldap2 find_entries: elapsed_time=%f', end_time-start_time)
+
if not res and not truncated:
raise errors.NotFound(reason='no such entry')
@@ -1381,4 +1385,3 @@ class ldap2(CrudBackend, Encoder):
return (len(output), output)
api.register(ldap2)
-
diff --git a/ipaserver/rpcserver.py b/ipaserver/rpcserver.py
index 83c5c2d..ffee3c6 100644
--- a/ipaserver/rpcserver.py
+++ b/ipaserver/rpcserver.py
@@ -293,6 +293,7 @@ class WSGIExecutioner(Executioner):
args = ()
options = {}
+start_time = time.time()
if not 'HTTP_REFERER' in environ:
return self.marshal(result, RefererError(referer='missing'), _id)
if not environ['HTTP_REFERER'].startswith('https://%s/ipa' % self.api.env.host) and not self.env.in_tree:
@@ -337,10 +338,11 @@ class WSGIExecutioner(Executioner):
# get at least some context of what is going on
params = options
principal = getattr(context, 'principal', 'UNKNOWN')
+end_time = time.time()
if error:
self.info('%s: %s(%s): %s', principal, name, ', '.join(self.Command[name]._repr_iter(**params)), e.__class__.__name__)
else:
-self.info('%s: %s(%s): SUCCESS', principal, name, ', '.join(self.Command[name]._repr_iter(**params)))
+self.info('%s: %s(%s): SUCCESS elapsed_time=%f', principal, name, ', '.join(self.Command[name]._repr_iter(**params)), end_time-start_time)
Re: [Freeipa-devel] slow response
On Mon, Jul 30, 2012 at 9:15 AM, John Dennis jden...@redhat.com wrote:
On 07/30/2012 11:30 AM, Stephen Ingram wrote:
On Wed, Jul 25, 2012 at 11:18 PM, Stephen Ingram sbing...@gmail.com
wrote:
On Wed, Jul 25, 2012 at 4:31 AM, John Dennis jden...@redhat.com wrote:
On 07/25/2012 02:59 AM, Stephen Ingram wrote:
Seeing python2.7, I'm guessing these patches were against Fedora.
Since I couldn't get them to apply against RH 6.3 I applied them by
hand. I couldn't get the WebUI to load after applying the patches. I'm
not sure of the code that caused the problem, but I did see mention of
global name datetime not being defined. You wouldn't happen to have
patches for RH 6.3?
Sorry, I thought you had a F17 install. It should be easy to fix the
datetime issue, just add this add the top of the file:
import time, datetime
If that simple fix doesn't work then let me know the version you've got
and
I'll make up a new patch against that version.
Yes, please send a patch for 2.20 with RH 6.3. The import time,
datetime did not address all of the errors.
Not sure if you missed this one or not, but, yes, I do need a patch
for 2.20 on RH 6.3. I added datetime, but there were still other
errors that I couldn't resolve.
Sorry, I did see it but I was busy with other things. You can try the
attached patch. However you need to have a clean set of files to patch
against. The patch command I suggested included the -b option and would have
created backup files of the original file with a .orig suffix. These are the
files the patch touches.
ipalib/session.py
ipaserver/plugins/ldap2.py
ipaserver/rpcserver.py
Find their .orig version and cp it back to the original filename. Then you
can try applying the patch again.
Caveat: I did not test this against 2.20, I just manually made the same set
of changes and generated a patch, it's possible in my hurry I made a mistake
you may need to tweak,
This is pretty much the same thing I applied previously by hand. I
noticed that you placed import datetime on its own line so I followed
suit. Here are the errors I'm receiving:
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.] mod_wsgi
(pid=2634): Exception occurred processing WSGI script
'/usr/share/ipa/wsgi.py'.
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] Traceback (most
recent call last):
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/share/ipa/wsgi.py, line 49, in application
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] return
api.Backend.wsgi_dispatch(environ, start_response)
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/lib/python2.6/site-packages/ipaserver/rpcserver.py, line 234,
in __call__
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] return
self.route(environ, start_response)
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/lib/python2.6/site-packages/ipaserver/rpcserver.py, line 246,
in route
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] return
app(environ, start_response)
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/lib/python2.6/site-packages/ipaserver/rpcserver.py, line 784,
in __call__
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] session_data =
session_mgr.load_session_data(environ.get('HTTP_COOKIE'))
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/lib/python2.6/site-packages/ipalib/session.py, line 1004, in
load_session_data
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x]
self.store_session_data(session_data)
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/lib/python2.6/site-packages/ipalib/session.py, line 1047, in
store_session_data
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x]
fmt_time(session_data['session_start_timestamp']),
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] File
/usr/lib/python2.6/site-packages/ipalib/session.py, line 634, in
fmt_time
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] return
datetime.fromtimestamp(timestamp).strftime(ISO8601_DATETIME_FMT)
[Mon Jul 30 10:09:09 2012] [error] [client x.x.x.x] AttributeError:
'module' object has no attribute 'fromtimestamp'
There seems to be a problem with the format of the log information
returned? Perhaps the fromtimestamp attribute was added after version
2.20?
Steve
___
Freeipa-devel mailing list
Freeipa-devel@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 07/30/2012 01:17 PM, Stephen Ingram wrote: This is pretty much the same thing I applied previously by hand. I noticed that you placed import datetime on its own line so I followed suit. Here are the errors I'm receiving: There seems to be a problem with the format of the log information returned? Perhaps the fromtimestamp attribute was added after version 2.20? sorry, that should be: return datetime.datetime.fromtimestamp(timestamp).strftime(ISO8601_DATETIME_FMT) In other words datetime has to be repeated twice. That's because fromtimestamp() is an attribute of the datetime class in the datetime module, thus the first datetime references the module and the second datetime references the datetime class in the datetime module. I wish I had a dime for every time I typed just a single datetime ;-) -- John Dennis jden...@redhat.com Looking to carve out IT costs? www.redhat.com/carveoutcosts/ ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
Stephen finally got his server patched with my timing instrumentation. He sent me his log file and I ran my script to parse it. The results are quite interesting. Basically I timed two things cmd_duration is the elapsed time to execute the IPA command. json_duration is the elapsed time to execute the JSON RPC containing the IPA command. The difference (delta) between the two is the time we spend doing session bookkeeping. In all but the first RPC we were executing from the session cache. Results are below. What is interesting is every command that executes from the session cache seems to have about a 1.5 second constant overhead. The other interesting bits are that most commands in the server execute quickly (from under a tenth of second to .3 second) and on average the server takes 1.5 seconds to respond to RPC (of which most of it appears to be in session code). What is taking so long with session bookkeeping? I don't know yet. I would need more timing instrumentation. I will say when I looked at the python-krb5 code (which we use to populate the ccache from the session and read back to store in the session) seemed to be remarkably inefficient. We also elected to use file based ccache rather than in-memory ccache (that means there is a bit of file-IO occurring). Has anyone used a Python profiler? Would that be better than adding instrumentation? BTW, the actual commands were stripped to protect data anonymity. cmd_duration: 0.107673 json_duration: 3.176758 delta: 3.069085 cmd_duration: 0.020068 json_duration: 1.543135 delta: 1.523067 cmd_duration: 0.387210 json_duration: 1.802954 delta: 1.415744 cmd_duration: 0.024086 json_duration: 1.405276 delta: 1.381190 cmd_duration: 0.342808 json_duration: 1.950365 delta: 1.607557 cmd_duration: 0.019286 json_duration: 1.398786 delta: 1.379500 cmd_duration: 0.200895 json_duration: 1.754358 delta: 1.553463 cmd_duration: 0.020293 json_duration: 1.410701 delta: 1.390408 cmd_duration: 0.383433 json_duration: 1.819478 delta: 1.436045 cmd_duration: 0.020350 json_duration: 1.406038 delta: 1.385688 cmd_duration: 0.346864 json_duration: 1.771281 delta: 1.424417 cmd_duration: 0.015998 json_duration: 1.707743 delta: 1.691745 cmd_duration: 0.314527 json_duration: 1.730894 delta: 1.416367 cmd_duration: 0.025323 json_duration: 1.582828 delta: 1.557505 -- John Dennis jden...@redhat.com Looking to carve out IT costs? www.redhat.com/carveoutcosts/ ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Wed, Jul 25, 2012 at 4:31 AM, John Dennis jden...@redhat.com wrote: On 07/25/2012 02:59 AM, Stephen Ingram wrote: Seeing python2.7, I'm guessing these patches were against Fedora. Since I couldn't get them to apply against RH 6.3 I applied them by hand. I couldn't get the WebUI to load after applying the patches. I'm not sure of the code that caused the problem, but I did see mention of global name datetime not being defined. You wouldn't happen to have patches for RH 6.3? Sorry, I thought you had a F17 install. It should be easy to fix the datetime issue, just add this add the top of the file: import time, datetime If that simple fix doesn't work then let me know the version you've got and I'll make up a new patch against that version. Yes, please send a patch for 2.20 with RH 6.3. The import time, datetime did not address all of the errors. Steve ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On Tue, Jul 24, 2012 at 11:09 AM, John Dennis jden...@redhat.com wrote:
On 07/24/2012 12:03 PM, Stephen Ingram wrote:
On Mon, Jul 23, 2012 at 11:25 AM, John Dennis jden...@redhat.com wrote:
On 07/23/2012 12:37 PM, John Dennis wrote:
Note the timestamps only have 1 second resolution, something
which would be easy to fix, so bear that in mind when looking at the
output of the script.
This is partially as a note to myself, but also to others who want to
test.
The following patch should produce timestamps in the debug output with
microsecond resolution.
No one seems to be jumping in on this. Should I run the test again
with this patch? I'm really interested in getting this resolved as I
can't help but think others are experiencing the same problem. I do
have a user in the system that is scheduled for deletion. Would it
help for you to grab a ticket with those credentials so you could
actually see the slowness in action?
It would be good to re-run your test with better timing information.
Attached is a patch that adds more timing information to the debug log
output. Please apply the patch and re-run your test the same way you did
before and email me the contents of /var/log/httpd/error_log. In the
error_log you should see lines with elapsed_time=, e.g.
INFO: ad...@xxx.xxx.xxx.xxx.xx: batch(({'params': ((), {}), 'method':
'ping'},)): SUCCESS elapsed_time=0.001663
To apply the patch you'll need to be root to modify the files, this should
work:
% su
% cd /usr/lib/python2.7/site-packages
% patch -p1 -b path_to_saved_patch_file
If you don't have patch installed:
% sudo yum install patch
Then restart httpd and re-run the test.
Seeing python2.7, I'm guessing these patches were against Fedora.
Since I couldn't get them to apply against RH 6.3 I applied them by
hand. I couldn't get the WebUI to load after applying the patches. I'm
not sure of the code that caused the problem, but I did see mention of
global name datetime not being defined. You wouldn't happen to have
patches for RH 6.3?
Steve
___
Freeipa-devel mailing list
Freeipa-devel@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 07/25/2012 02:59 AM, Stephen Ingram wrote: Seeing python2.7, I'm guessing these patches were against Fedora. Since I couldn't get them to apply against RH 6.3 I applied them by hand. I couldn't get the WebUI to load after applying the patches. I'm not sure of the code that caused the problem, but I did see mention of global name datetime not being defined. You wouldn't happen to have patches for RH 6.3? Sorry, I thought you had a F17 install. It should be easy to fix the datetime issue, just add this add the top of the file: import time, datetime If that simple fix doesn't work then let me know the version you've got and I'll make up a new patch against that version. -- John Dennis jden...@redhat.com Looking to carve out IT costs? www.redhat.com/carveoutcosts/ ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 07/24/2012 12:03 PM, Stephen Ingram wrote:
On Mon, Jul 23, 2012 at 11:25 AM, John Dennis jden...@redhat.com wrote:
On 07/23/2012 12:37 PM, John Dennis wrote:
Note the timestamps only have 1 second resolution, something
which would be easy to fix, so bear that in mind when looking at the
output of the script.
This is partially as a note to myself, but also to others who want to test.
The following patch should produce timestamps in the debug output with
microsecond resolution.
No one seems to be jumping in on this. Should I run the test again
with this patch? I'm really interested in getting this resolved as I
can't help but think others are experiencing the same problem. I do
have a user in the system that is scheduled for deletion. Would it
help for you to grab a ticket with those credentials so you could
actually see the slowness in action?
It would be good to re-run your test with better timing information.
Attached is a patch that adds more timing information to the debug log
output. Please apply the patch and re-run your test the same way you did
before and email me the contents of /var/log/httpd/error_log. In the
error_log you should see lines with elapsed_time=, e.g.
INFO: ad...@xxx.xxx.xxx.xxx.xx: batch(({'params': ((), {}), 'method':
'ping'},)): SUCCESS elapsed_time=0.001663
To apply the patch you'll need to be root to modify the files, this
should work:
% su
% cd /usr/lib/python2.7/site-packages
% patch -p1 -b path_to_saved_patch_file
If you don't have patch installed:
% sudo yum install patch
Then restart httpd and re-run the test.
--
John Dennis jden...@redhat.com
Looking to carve out IT costs?
www.redhat.com/carveoutcosts/
diff --git a/ipalib/session.py b/ipalib/session.py
index 4b783bb..1cff222 100644
--- a/ipalib/session.py
+++ b/ipalib/session.py
@@ -628,9 +628,9 @@ mod_auth_kerb. Everything else remains the same.
default_max_session_duration = 60*60 # number of seconds
-ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S' # FIXME jrd, this should be defined elsewhere
+ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S.%f' # FIXME jrd, this should be defined elsewhere
def fmt_time(timestamp):
-return time.strftime(ISO8601_DATETIME_FMT, time.localtime(timestamp))
+return datetime.fromtimestamp(timestamp).strftime(ISO8601_DATETIME_FMT)
#---
diff --git a/ipaserver/plugins/ldap2.py b/ipaserver/plugins/ldap2.py
index 6a3d216..c615a7d 100644
--- a/ipaserver/plugins/ldap2.py
+++ b/ipaserver/plugins/ldap2.py
@@ -715,6 +715,7 @@ class ldap2(CrudBackend, Encoder):
attrs_list = list(set(attrs_list))
# pass arguments to python-ldap
+start_time = time.time()
try:
id = self.conn.search_ext(
base_dn, scope, filter, attrs_list, timeout=time_limit,
@@ -733,6 +734,9 @@ class ldap2(CrudBackend, Encoder):
except _ldap.LDAPError, e:
_handle_errors(e)
+end_time = time.time()
+root_logger.debug('ldap2 find_entries: elapsed_time=%f', end_time-start_time)
+
if not res and not truncated:
raise errors.NotFound(reason='no such entry')
@@ -1363,4 +1367,3 @@ class ldap2(CrudBackend, Encoder):
return (len(output), output)
api.register(ldap2)
-
diff --git a/ipaserver/rpcserver.py b/ipaserver/rpcserver.py
index c770290..d290276 100644
--- a/ipaserver/rpcserver.py
+++ b/ipaserver/rpcserver.py
@@ -305,6 +305,7 @@ class WSGIExecutioner(Executioner):
args = ()
options = {}
+start_time = time.time()
if not 'HTTP_REFERER' in environ:
return self.marshal(result, RefererError(referer='missing'), _id)
if not environ['HTTP_REFERER'].startswith('https://%s/ipa' % self.api.env.host) and not self.env.in_tree:
@@ -349,10 +350,11 @@ class WSGIExecutioner(Executioner):
# get at least some context of what is going on
params = options
principal = getattr(context, 'principal', 'UNKNOWN')
+end_time = time.time()
if error:
self.info('%s: %s(%s): %s', principal, name, ', '.join(self.Command[name]._repr_iter(**params)), e.__class__.__name__)
else:
-self.info('%s: %s(%s): SUCCESS', principal, name, ', '.join(self.Command[name]._repr_iter(**params)))
+self.info('%s: %s(%s): SUCCESS elapsed_time=%f', principal, name, ', '.join(self.Command[name]._repr_iter(**params)), end_time-start_time)
else:
self.info('%s: %s', context.principal, e.__class__.__name__)
return self.marshal(result, error, _id)
@@ -791,6 +793,7 @@ class jsonserver_session(jsonserver, KerberosSession):
'''
'''
+start_time = time.time()
self.debug('WSGI jsonserver_session.__call__:')
# Load the session data
@@ -852,6 +855,8 @@ class
[Freeipa-devel] slow response (was: 2.20 dirsrv memory usage)
Stephen provided Alexander and myself with debug output. I quickly wrote
a little script to parse the output looking for the session timestamps,
what commands were executed for each RPC, and computed the duration of
the RPC. Note the timestamps only have 1 second resolution, something
which would be easy to fix, so bear that in mind when looking at the
output of the script.
The script first lists every command executed in the RPC (including
internal commands), which is then followed by the duration for the RPC.
From the error_log it appears as if the session cache is being used for
all RPC commands.
--
John Dennis jden...@redhat.com
Looking to carve out IT costs?
www.redhat.com/carveoutcosts/
commands:
batch(({u'params': [[], {}], u'method': u'i18n_messages'}, {u'params': [[],
{u'all': True, u'whoami': True}], u'method': u'user_find'}, {u'params': [[],
{}], u'method': u'env'}, {u'params': [[], {}], u'method': u'dns_is_enabled'}))
i18n_messages()
user_find(None, whoami=True, all=True)
env(None)
dns_is_enabled()
command duration: 0:00:02
commands:
json_metadata(None, None, command=u'all')
json_metadata(None, None, object=u'all')
command duration: 0:00:03
commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01
commands:
batch(({u'params': [[u'admin'], {u'all': True}], u'method': u'user_show'},
{u'params': [[u'alyce'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'apickens'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'carolyn'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'carolynvm'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'cwoodring'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'cyrus'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'dawnselleck'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'doug'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'erika'],
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'jbn'], {u'all':
True}], u'method': u'user_show'}, {u'params': [[u'jessica'], {u'all': True}],
u'method': u'user_show'}, {u'params': [[u'jimmy'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'john'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'jschiefer'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'jshirkani'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'kaline'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'kaline2'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'kbiorac'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'ken'], {u'all': True}], u'method':
u'user_show'}))
user_show(u'admin', all=True)
user_show(u'alyce', all=True)
user_show(u'apickens', all=True)
user_show(u'carolyn', all=True)
user_show(u'carolynvm', all=True)
user_show(u'cwoodring', all=True)
user_show(u'cyrus', all=True)
user_show(u'dawnselleck', all=True)
user_show(u'doug', all=True)
user_show(u'erika', all=True)
user_show(u'jbn', all=True)
user_show(u'jessica', all=True)
user_show(u'jimmy', all=True)
user_show(u'john', all=True)
user_show(u'jschiefer', all=True)
user_show(u'jshirkani', all=True)
user_show(u'kaline', all=True)
user_show(u'kaline2', all=True)
user_show(u'kbiorac', all=True)
user_show(u'ken', all=True)
command duration: 0:00:01
commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01
commands:
batch(({u'params': [[u'kenbrisbin'], {u'all': True}], u'method': u'user_show'},
{u'params': [[u'lbrown'], {u'all': True}], u'method': u'user_show'},
{u'params': [[u'lew'], {u'all': True}], u'method': u'user_show'}, {u'params':
[[u'lisa'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'liz'],
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'manerriza'],
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'mastering'],
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'mustangsally27'],
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'nancy'], {u'all':
True}], u'method': u'user_show'}, {u'params': [[u'ngimblin'], {u'all': True}],
u'method': u'user_show'}, {u'params': [[u'om'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'orderskb'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'pmccuin'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'reinmiller'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'reinmiller2'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'renee'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'robertson'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'robertson2'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'royer'], {u'all': True}], u'method':
u'user_show'}, {u'params': [[u'ruben'], {u'all': True}], u'method':
u'user_show'}))
user_show(u'kenbrisbin', all=True)
user_show(u'lbrown', all=True)
user_show(u'lew', all=True)
user_show(u'lisa', all=True)
Re: [Freeipa-devel] slow response
Darn it. I just realized I did something really dumb. I posted material to a public list that should have been kept private. I'm even the one who asked Stephen to keep the information private. I offer Stephen my sincerest apology for being a complete idiot and I hope I didn't create any problems for you. John (with his tail between his legs) -- John Dennis jden...@redhat.com Looking to carve out IT costs? www.redhat.com/carveoutcosts/ ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 07/23/2012 01:23 PM, Stephen Ingram wrote: On Mon, Jul 23, 2012 at 9:37 AM, John Dennis jden...@redhat.com wrote: Stephen provided Alexander and myself with debug output. I quickly wrote a little script to parse the output looking for the session timestamps, what commands were executed for each RPC, and computed the duration of the RPC. Note the timestamps only have 1 second resolution, something which would be easy to fix, so bear that in mind when looking at the output of the script. The script first lists every command executed in the RPC (including internal commands), which is then followed by the duration for the RPC. From the error_log it appears as if the session cache is being used for all RPC commands. I see the times all appear to be smaller than what is experienced in the Web UI itself. So what is happening the rest of the 3-4 seconds? Is that taken up by the ticket request? No, based on what I see in the error_log file the ticket request is not a factor. The error_log shows you acquired a ticket exactly once on the first command and from that point forward your credentials were served from the session cache (as we would hope/expect). Caveat, I did not examine the network traffic log, just the error_log. I don't know where the lost time seems to be or if the execution times seen by the analysis are expected (we should also increase the resolution of the timestamp). I was hoping other developers might chime in with their own thoughts. -- John Dennis jden...@redhat.com Looking to carve out IT costs? www.redhat.com/carveoutcosts/ ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
Re: [Freeipa-devel] slow response
On 07/23/2012 12:37 PM, John Dennis wrote: Note the timestamps only have 1 second resolution, something which would be easy to fix, so bear that in mind when looking at the output of the script. This is partially as a note to myself, but also to others who want to test. The following patch should produce timestamps in the debug output with microsecond resolution. -- John Dennis jden...@redhat.com Looking to carve out IT costs? www.redhat.com/carveoutcosts/ diff --git a/ipalib/session.py b/ipalib/session.py index 4b783bb..1cff222 100644 --- a/ipalib/session.py +++ b/ipalib/session.py @@ -628,9 +628,9 @@ mod_auth_kerb. Everything else remains the same. default_max_session_duration = 60*60 # number of seconds -ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S' # FIXME jrd, this should be defined elsewhere +ISO8601_DATETIME_FMT = '%Y-%m-%dT%H:%M:%S.%f' # FIXME jrd, this should be defined elsewhere def fmt_time(timestamp): -return time.strftime(ISO8601_DATETIME_FMT, time.localtime(timestamp)) +return datetime.fromtimestamp(timestamp).strftime(ISO8601_DATETIME_FMT) #--- ___ Freeipa-devel mailing list Freeipa-devel@redhat.com https://www.redhat.com/mailman/listinfo/freeipa-devel
