8 Replies Latest reply on Nov 15, 2019 5:36 AM by Adam Kowalski

    Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..

    Adam Kowalski
      Share This:

      AR System version : 9.1.02.003 201704191747

      Mid-Tier version:  9.1.02 201611252320

       

       

       

      Hello,

       

      We are observed slow system performance during closing, progressing, adding notes into a ticket etc. When end users closing tickets sometimes whole browser freezes. Adding notes taking up to 2 minutes. This is happens randomly. Some parameters have been changed in config files, however, system performance is still slow.

       

      JVM Heap Size has been increased from 512m to 2048m.

      Private-RPC-Sockets settings have been changed as follows: 

       

      Private-RPC-Socket: 390620 3 12

      Private-RPC-Socket: 390635 5 8

      To

      Private-RPC-Socket: 390620 16 24

      Private-RPC-Socket: 390635 16 24

       

      In arserver.config below parameters have been change:

      From

      1. jvm.minimum.heap.size=8589934592
      2. jvm.maximum.heap.size=8589934592

      To

      1. jvm.minimum.heap.size=12884901888
      2. jvm.maximum.heap.size=12884901888

       

       

      Could you please advice what can be the root cause of this behavior?

       

      Best Regards,

      Adam

        • 1. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
          Marek Ceizel

          Hi Adam,

           

          What is your Server RAM (is this a single server?). What is your page file size setting ?

          Do you know the forms:

          Server Statistics: Longest SQLs

          Server Statistics: Longest APIs

          ?

           

          In SQL you can search for some long runners and check why (indexing?).

           

          regards

          Marek

          • 2. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
            rodrigo barcat

            Hello Adam Kowalski

             

            Complementing Marek's post, do you have any customization running at the time the ticket is closed?

            When you mentioned tickets, which ticket? Incident, change, problems, work order, everyone?

             

            Collect SQL and API (together on the same file) during the ticket closure and attach it here, please (if you can share it with us). If not, download ARLog Analyzer and try to understand system queries to improve you DB(if necessary).

            • 3. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
              Adam Kowalski

              Hi Marek, Rodrigo,

               

              2 AR servers - 32 Gb RAM each

              What is your page file size setting - 4864 mb

               

              Server Statistics: Longest SQLs - the form does not contain any entry

              Server Statistics: Longest APIs - the form does not contain any entry

               

              Complementing Marek's post, do you have any customization running at the time the ticket is closed? - we have some filters but nothing major.

               

              When you mentioned tickets, which ticket? Incident, change, problems, work order, everyone? - Incident Management

               

              Below are some examples of longest calls:

               

              ++++++++++++

              1. +GLEWF ARGetListEntryWithFields -- schema HPD:Help Desk

              <API > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:24.8190 */ +GLEWF   ARGetListEntryWithFields -- schema HPD:Help Desk from Mid-tier (protocol 23) at IP address 10.17.5.88 using RPC // :q:0.0s

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:37:24.8190 */ BEGIN TRANSACTION

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:37:24.8220 */ Generating prepared statement

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:24.8220 */ OK

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:24.8220 */ Binding [3] parameters to prepared statement

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:24.8220 */ OK

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:24.8220 */ WITH AR_SQL_Alias$1 AS (SELECT T1436.C1000000161, T1436.C1000000018, T1436.C1000000019, T1436.C1000000000, T1436.C303497300, T1436.C1000000164, T1436.C7, T1436.C1000000217, T1436.C1000000218, T1436.C1000005261, T1436.C1000003009, T1436.C1, ROW_NUMBER() OVER (ORDER BY T1436.C1000000161 DESC, T1436.C1 ASC) AS 'AR_RowNumber_Alias$1' FROM T1436 WHERE (T1436.C599992119 LIKE N'%1032255%')) SELECT AR_SQL_Alias$1.C1000000161, AR_SQL_Alias$1.C1000000018, AR_SQL_Alias$1.C1000000019, AR_SQL_Alias$1.C1000000000, AR_SQL_Alias$1.C303497300, AR_SQL_Alias$1.C1000000164, AR_SQL_Alias$1.C7, AR_SQL_Alias$1.C1000000217, AR_SQL_Alias$1.C1000000218, AR_SQL_Alias$1.C1000005261, AR_SQL_Alias$1.C1000003009, AR_SQL_Alias$1.C1 FROM AR_SQL_Alias$1 WHERE (AR_SQL_Alias$1.AR_RowNumber_Alias$1 BETWEEN 0 AND 1001)

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:38:18.6810 */ OK

              <SQL > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:38:18.6810 */ COMMIT TRANSACTION

              <API > <TID: 0000000376> <RPC ID: 0007703819> <Queue: List      > <Client-RPC: 390620   > <USER: cp46011 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:38:18.6820 */ -GLEWF            OK

               

              Time Taken: 53.8630 sec

               

              1. +GLEWF ARGetListEntryWithFields -- schema HPD:Help Desk

              <API > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:11.2020 */ +GLEWF   ARGetListEntryWithFields -- schema HPD:Help Desk from Mid-tier (protocol 23) at IP address 10.17.5.87 using RPC // :q:0.0s

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:11.2020 */ BEGIN TRANSACTION

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:11.2050 */ Generating prepared statement

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:11.2050 */ OK

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:11.2050 */ Binding [3] parameters to prepared statement

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:11.2050 */ OK

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:40:11.2050 */ WITH AR_SQL_Alias$1 AS (SELECT T1436.C1000000161, T1436.C1000000018, T1436.C1000000019, T1436.C1000000000, T1436.C303497300, T1436.C1000000164, T1436.C7, T1436.C1000000217, T1436.C1000000218, T1436.C1000005261, T1436.C1000003009, T1436.C1, ROW_NUMBER() OVER (ORDER BY T1436.C1000000161 DESC, T1436.C1 ASC) AS 'AR_RowNumber_Alias$1' FROM T1436 WHERE (T1436.C1000000000 LIKE N'%pack label%')) SELECT AR_SQL_Alias$1.C1000000161, AR_SQL_Alias$1.C1000000018, AR_SQL_Alias$1.C1000000019, AR_SQL_Alias$1.C1000000000, AR_SQL_Alias$1.C303497300, AR_SQL_Alias$1.C1000000164, AR_SQL_Alias$1.C7, AR_SQL_Alias$1.C1000000217, AR_SQL_Alias$1.C1000000218, AR_SQL_Alias$1.C1000005261, AR_SQL_Alias$1.C1000003009, AR_SQL_Alias$1.C1 FROM AR_SQL_Alias$1 WHERE (AR_SQL_Alias$1.AR_RowNumber_Alias$1 BETWEEN 0 AND 1001)

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:50.1050 */ OK

              <SQL > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:50.1060 */ COMMIT TRANSACTION

              <API > <TID: 0000000380> <RPC ID: 0007706536> <Queue: List      > <Client-RPC: 390620   > <USER: fm46004 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:40:50.1060 */ -GLEWF            OK

               

              Time Taken: 38.9040 sec

               

              1. +SVE ARServiceEntry -- schema HPD:Incident Management Console

              <API > <TID: 0000000343> <RPC ID: 0007709562> <Queue: Fast      > <Client-RPC: 390620   > <USER: xfc0003 > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:45:47.5220 */ +SVE     ARServiceEntry -- schema HPD:Incident Management Console entryId NULL from Mid-tier (protocol 23) at IP address 10.17.5.88 using RPC // :q:0.0s

              <SQL > <TID: 0000000343> <RPC ID: 0007709562> <Queue: Fast      > <Client-RPC: 390620   > <USER: xfc0003 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:45:47.5320 */ WITH AR_SQL_Alias$1 AS (SELECT T1436.C1000000161, T1436.C1, ROW_NUMBER() OVER (ORDER BY T1436.C1000000161 DESC, T1436.C1 ASC) AS 'AR_RowNumber_Alias$1' FROM T1436 WHERE (((N'NSG Group' = T1436.C1000000001) OR (N'NSG Group' IS NULL)) AND (T1436.C7 < 4) AND ((T1436.C1000000079 = N'SGP000000000733') OR (T1436.C1000000427 = N'SGP000000000733') OR (T1436.C1000000079 = N'SGP000000000514') OR (T1436.C1000000427 = N'SGP000000000514') OR (T1436.C1000000079 = N'SGP000000005128') OR (T1436.C1000000427 = N'SGP000000005128') OR (T1436.C1000000079 = N'SGP000000003119') OR (T1436.C1000000427 = N'SGP000000003119') OR (T1436.C1000000079 = N'SGP000000003129') OR (T1436.C1000000427 = N'SGP000000003129') OR (T1436.C1000000079 = N'SGP000000003523') OR (T1436.C1000000427 = N'SGP000000003523') OR (T1436.C100...

              <SQL > <TID: 0000000343> <RPC ID: 0007709562> <Queue: Fast      > <Client-RPC: 390620   > <USER: xfc0003 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:46:10.2210 */ OK

              <SQL > <TID: 0000000343> <RPC ID: 0007709562> <Queue: Fast      > <Client-RPC: 390620   > <USER: xfc0003                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:46:10.2210 */ SELECT COUNT(*) FROM T1436 WHERE (((N'NSG Group' = T1436.C1000000001) OR (N'NSG Group' IS NULL)) AND (T1436.C7 < 4) AND ((T1436.C1000000079 = N'SGP000000000733') OR (T1436.C1000000427 = N'SGP000000000733') OR (T1436.C1000000079 = N'SGP000000000514') OR (T1436.C1000000427 = N'SGP000000000514') OR (T1436.C1000000079 = N'SGP000000005128') OR (T1436.C1000000427 = N'SGP000000005128') OR (T1436.C1000000079 = N'SGP000000003119') OR (T1436.C1000000427 = N'SGP000000003119') OR (T1436.C1000000079 = N'SGP000000003129') OR (T1436.C1000000427 = N'SGP000000003129') OR (T1436.C1000000079 = N'SGP000000003523') OR (T1436.C1000000427 = N'SGP000000003523') OR (T1436.C1000000079 = N'SGP000000003134') OR (T1436.C1000000427 = N'SGP000000003134') OR (T1436.C1000000079 = N'SGP000000003140') OR (T1436.C1000000...

              <SQL > <TID: 0000000343> <RPC ID: 0007709562> <Queue: Fast      > <Client-RPC: 390620   > <USER: xfc0003                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:46:20.9770 */ OK

              <API > <TID: 0000000343> <RPC ID: 0007709562> <Queue: Fast      > <Client-RPC: 390620   > <USER: xfc0003 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:46:21.1310 */ -SVE              OK

               

              Time Taken: 33.6090

              Note: Due to huge API Calls I have shared above steps for Start of API Call, Start of SQL Call, End of SQL Call and End of API Call.

               

              1. +CE ARCreateEntry -- schema HPD:WorkLog

              <API > <TID: 0000000429> <RPC ID: 0007704059> <Queue: Fast      > <Client-RPC: 390620   > <USER: shizukasawauchi > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:42.4300 */ +CE      ARCreateEntry -- schema HPD:WorkLog from Mid-tier (protocol 23) at IP address 10.17.5.87 using RPC // :q:0.0s

              <SQL > <TID: 0000000429> <RPC ID: 0007704059> <Queue: Fast      > <Client-RPC: 390620   > <USER: shizukasawauchi > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:37:42.6140 */ WITH AR_SQL_Alias$1 AS (SELECT T1914.C1000000829, T1914.C304309600, T1914.C304309590, T1914.C301723100, T1914.C301386300, T1914.C301386100, T1914.C301289100, T1914.C10006803, T1914.C10006800, T1914.C10001963, T1914.C10001959, T1914.C10001954, T1914.C10001953, T1914.C10001952, T1914.C10001951, T1914.C10001950, B1914C10001831.C10001831 BLOB_10001831, B1914.C10001831, B1914.CO10001831, B1914.CC10001831, T1914.C10001821, T1914.C10000101, T1914.C2, T1914.C1, ROW_NUMBER() OVER (ORDER BY T1914.C1 ASC) AS 'AR_RowNumber_Alias$1' FROM T1914 LEFT JOIN B1914 ON (T1914.C1 = B1914.C1) LEFT JOIN B1914C10001831 ON (B1914.C1 = B1914C10001831.entryId) WHERE ((T1914.C304309590 = N'HPD:WorkLog') AND (T1914.C304309600 = N'AGGAA5V0FL28KAPZBM4UPYDZGQM9GU'))) SELECT AR_SQL_Alias$1.C1000000829, AR_SQL_Alias$1....

              <SQL > <TID: 0000000429> <RPC ID: 0007704059> <Queue: Fast      > <Client-RPC: 390620   > <USER: shizukasawauchi > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:38:10.5830 */ OK

              <API > <TID: 0000000429> <RPC ID: 0007704059> <Queue: Fast      > <Client-RPC: 390620   > <USER: shizukasawauchi > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:38:10.7340 */ -CE               OK -- New ID WLG000008398684

               

              Time Taken: 28.3040 Sec

              Note: Due to huge API Calls I have shared above steps for Start of API Call, Start of SQL Call, End of SQL Call and End of API Call.

               

              1. +GLEWF ARGetListEntryWithFields -- schema SRM:Request

              <API > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:42:47.6660 */ +GLEWF   ARGetListEntryWithFields -- schema SRM:Request from Mid-tier (protocol 23) at IP address 10.17.5.87 using RPC // :q:0.0s

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:42:47.6670 */ BEGIN TRANSACTION

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:42:47.6710 */ Generating prepared statement

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:42:47.6710 */ OK

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:42:47.6710 */ Binding [10] parameters to prepared statement

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:42:47.6710 */ OK

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587                                      > <Overlay-Group: 1         > /* Tue Oct 08 2019 08:42:47.6710 */ WITH AR_SQL_Alias$1 AS (SELECT T1905.C302829600, T1905.C303440700, T1905.C302890100, T1905.C1000000829, T1905.C301244700, T1905.C7, T1905.C303490700, T1905.C3, T1905.C1000000150, T1905.C303490600, T1905.C303051500, T1905.C302791600, T1905.C302881500, T1905.C301464300, T1905.C301464400, T1905.C1, T1905.C179, T1905.C301303200, T1905.C302825900, T1905.C302826500, T1905.C1000000162, T1905.C303490500, T1905.C302830300, T1905.C1000000337, T1905.C1000000338, T1905.C2, T1905.C1000001181, T1905.C303472300, T1905.C304278110, T1905.C1000003297, T1905.C1000003298, T1905.C1000000019, T1905.C1000000018, T1905.C304234600, T1905.C301438012, T1905.C1000003264, T1905.C304367211, T1905.C301378004, T1905.C301289100, ROW_NUMBER() OVER (ORDER BY T1905.C3 DESC, T1905.C1 ASC) AS 'AR_RowNumber_Alias$1' FROM T1...

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:43:04.7370 */ OK

              <SQL > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:43:04.7380 */ COMMIT TRANSACTION

              <API > <TID: 0000000376> <RPC ID: 0007708138> <Queue: List      > <Client-RPC: 390620   > <USER: ga46587 > <Overlay-Group: 1 > /* Tue Oct 08 2019 08:43:04.7580 */ -GLEWF            OK

               

              Time Taken: 17.0920

              ++++++++++++

              • 4. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
                rodrigo barcat

                And when you paste these queries into Oracle and analyze it there, what is the oracle output? Does it show you how your index usage is doing?

                • 5. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
                  Carl Wilson

                  Hi,

                  looking at the above SQL calls, it appears your system would benefit from some indexing to decrease the time SQL takes to process.

                  Working with your DBA (and Remedy functionality), you should be able to identify the largest queries that are taking the most time and optimize these.

                   

                  Cheers

                  Carl

                  2 of 2 people found this helpful
                  • 6. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
                    rodrigo barcat

                    Adam Kowalski

                     

                    Run the select above to find some queries that spent a lot of time to be executed.

                     

                    select a.sid, a.serial#, a.username, a.start_time, (a.totalwork - a.sofar)/100 execution_time, b.sql_text

                    from gv$session_longops a, v$sql b

                    where a.sql_address = b.address

                    and a.sofar <> a.totalwork

                     

                    You need ask to your dba to grant access on gv$session_longops and v$sql

                    2 of 2 people found this helpful
                    • 7. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
                      Robert Poulos

                      A few things stand out to me.  One, some of your queries got truncated in the log at a point that prevents you from seeing the WHERE clause.  For troubleshooting purposes you can always temporarily configure this to see the entire statement logged:

                       

                      Enable-Unlimited-Log-Line-Length: T

                       

                      And second, where we do see the WHERE clause we see a few examples like this:

                       

                      WHERE (T1436.C599992119 LIKE N'%1032255%')

                      WHERE (T1436.C1000000000 LIKE N'%pack label%')

                       

                      Qualifiers like these will always be problematic for large tables because of the LIKE and the wildcards.  There are lots of write-ups regarding the database not being able to optimize the use of indexes in this case.  Did end users generate these qualifiers?  The calls came from Mid-tier.  Try some queries like this using a SQL tool and verify what the performance is.

                       

                      Regards,

                       

                      Bob P.

                      3 of 3 people found this helpful
                      • 8. Re: Remedy 9 system slow performance during ticket closure, progressing, adding notes etc..
                        Adam Kowalski

                        This case is now resolved. We have business object connected to main sql db server rather than backup server. All instances of scheduled reports have been set up on every 5 minutes and even some of them every 2-3 minutes (especially in the morning and afternoon). The same scheduled reports have been generated from smart reporting system as we have started this project recently and moved all reports there from BO.

                         

                        In the summary actions have been taken:

                         

                        Rebuild of indexes on live sql DB,

                        Switched off unqualified searches in configuration tab,

                        Increase java heap size from 12gb to 16gb,

                        Switched off 43 instances from BO.

                         

                        After above steps, performance has been increased a lot.

                         

                        Thank you all for your suggestions!

                         

                        Best Regards,

                        Adam