Showing posts with label Concurrent Manager. Show all posts
Showing posts with label Concurrent Manager. Show all posts
Monday, March 7, 2016
R12: Programs complete in Warning due to "Output Post-processor is Running But Has Not Picked up This Request"
Article "R12: Various Programs End With Warning: The Output Post-processor is Running But Has Not Picked up This Request" in My Oracle Support refers to R12.0.6 in document ID 1224684.1 BUT has a lot of information about the setup of the Concurrent Manager and Output Post Processor so it is a good one to read up on even if you know about this and have patched to help prevent the issue from happening!
Thursday, February 4, 2016
R12 EBS: Output Post Processor not working due to JVM error
The article "EBS: OPP does not work After Platform Migration ; Conflicting Collector Combinations ; Could not Create the Java Virtual Machine" can be found on My Oracle Support via note ID 2103349.1 which tells us why this happened AND also more details that could be useful in your toolbox about "developer parameters" or environmental files being used!
Friday, November 20, 2015
R12.1.3: Internal Concurrent Manager does not manage processes correctly after CPU patches applied
Regardless if you have already applied the CPU patch which causes this or not, you need to prepare for the potential to encounter the "Concurrent Managers Are Not Going Down Properly After Appling Patch 16735285 in R12(12.1.3)" issue reported in MOS document ID 2063862.1 after any change so make sure you add this to your test cases immediately! You could also have another take away by finding out more about the Concurrent Managers by looking up the package FND_CONC_RAC_UTILS reported in the error message to see if there are other procedures that maybe you could utilize in the future!!
Friday, August 7, 2015
Weekend Learning: Profile options for EBS Concurrent Manager
Ever wonder if there are profile options which may impact the Concurrent Manager in the EBS application, that you might not know about? Then check out this article "Report Manager Profile Options" from My Oracle Support note 1521253.1 to learn more about profile options that impact modules like BNE, GL, and more!
Tuesday, March 10, 2015
R12.1.3 Concurrent Manager: Buttons greyed out on scheduled requests
Have you applied a recent R12.1.3 patch? If you have, then your version of FNDRSRUN may have a bug in it and the article "Options Button Is Greyed Out For Future Scheduled Request Sets" found in My Oracle Support from note ID 1988337.1 tells you what patch caused this and which one resolves the issue.
Thursday, September 18, 2014
Concurrent Manager: Killed/Giving Up
Troubleshooting a situation with our Concurrent Manager on 11.5.10.2 I ran into a problem I have never seen before. Running similar to researching an issue like a previous post, I was trying to find out why the OS thread for the Internal Manager was taking CPU cycles and when I looked in the Administer Concurrent Manager form I can see that the Internal Manager had been up for months. First thing I try is to Verify it, but that and every other step I was taking would end up just Pending so I started digging for why we needed the CM to be bounced.
In the Internal Manager log I could see the following entry:
Process monitor session ended : <date>
Process monitor session started : <date>
(the above were repeated hundreds of times)
Killed
The SID_processID@SID internal concurrent manager has terminated with status 137 - giving up.
What is interesting, is that the <date> above was many months prior to when I tried to give the Internal Manager the Verify command. What does this mean? Well we have another opportunity to proactively monitor our log files for this known issue!
In the Internal Manager log I could see the following entry:
Process monitor session ended : <date>
Process monitor session started : <date>
(the above were repeated hundreds of times)
Killed
The SID_processID@SID internal concurrent manager has terminated with status 137 - giving up.
What is interesting, is that the <date> above was many months prior to when I tried to give the Internal Manager the Verify command. What does this mean? Well we have another opportunity to proactively monitor our log files for this known issue!
Thursday, July 31, 2014
R12: Activating Parallel Concurrent Processing
If you are going to R12, or have just gone to it, the article "How To Activate Parallel Concurrent Processing In R12" from My Oracle Support note ID 1525233.1 is a good overview of how to use the Parallel Concurrent Processing. I say use, because it is on by default with R12 so it would probably be best to understand how the Generic Service Management interacts with the Internal Concurrent Manager right?
Monday, May 26, 2014
Concurrent Processing - Information Center
Have you ever wanted to learn more about the Concurrent Manager, know more about concurrent processing in general for your EBS application, or even try to stay on top of current known bugs and issues out there for the CM? Look no further! My Oracle Support's article "Concurrent Processing - Product Information Center (PIC)" found in note 1304305.1 is your one stop shop for everything related to the Concurrent Manager with at least a hundred, if not twice that number, articles linked from the page so you can favorite it and stay on top of the latest updates!
Wednesday, March 12, 2014
URGENT R12: Complete Concurrent Manager processing stop
Hot off the presses is an urgent update for anybody on R12 or planning on going to R12. Today we encountered an issue where our users reported their concurrent requests were ending in Error, and in the log file was "emsg:was terminated by signal 25" but we didn't know of anything wrong or why this would be happening. My co-worker searched on MOS and found note 842850.1 which is directly on point indicating that once the reports.log file in $APPLCSF/$APPLLOG or $INST_TOP (ours was in $FND_TOP) grows to be 2GB concurrent processing stops. All reports, no matter how many nodes you have if it's all on a shared directory structure, come to a complete dead stop.
Luckily we didn't have any critical business processes die because of this, but you need to take steps immediately to make sure you don't encounter this same situation which could happen while reports are being run that could cause orphan records or incomplete data to be left in your system. Our DBA was able to follow the action listed in the note without taking the Concurrent Manager down, so I don't know if that will cause a part 2 for this document or not, but I'll keep you updated if we encounter any issues because of that.
What is also interesting about this, is that our DBAs did encounter this is problem in QA during their building and maintenance of R12 and applied patch 10152652 which is notated as fixing this issue when we went to PROD but it did not work for us today. That is probably why the note was updated within the last week. :}
Luckily we didn't have any critical business processes die because of this, but you need to take steps immediately to make sure you don't encounter this same situation which could happen while reports are being run that could cause orphan records or incomplete data to be left in your system. Our DBA was able to follow the action listed in the note without taking the Concurrent Manager down, so I don't know if that will cause a part 2 for this document or not, but I'll keep you updated if we encounter any issues because of that.
What is also interesting about this, is that our DBAs did encounter this is problem in QA during their building and maintenance of R12 and applied patch 10152652 which is notated as fixing this issue when we went to PROD but it did not work for us today. That is probably why the note was updated within the last week. :}
Saturday, January 18, 2014
Weekend Reading: Concurrent Manager
Maris Elsins posted several great posts many months ago on the internals of the Concurrent Manager processing, some performance settings available, and the dangers of CMCLEAN being run. Why have I not posted these sooner you ask? Well, I'm anxiously waiting for the next entries in this series but I found myself reading these again so I decided there was no better time to share them with you! Very easy to read, but explaining some advanced mechanisms with the Concurrent and some great visual aids as well.
Wednesday, October 9, 2013
Concurrent Manager and APPLPTMP parameter
Digesting the information in this article, it reminds me that sometimes it is the smallest of items which have the largest of impacts. While the author starts off telling us about the ORA-20100 error encountered for FND_FILE, the important meat here is what the parameter $APPLPTMP is and just how it is different from APPLTMP. I found this interesting because I'm not quite sure what $APPLPTMP is set to in our environment, and I'd like to investigate this a bit more in 11i as well as when we go to R12.
Sunday, September 29, 2013
Disconnected Concurrent Manager
Due to a network issue the other night, I got to see interesting error messages, starting with from the Oracle Alert product:
APP-FND-01564: ORACLE error 12203 in AFPCOA
Cause: AFPCOA failed due to ORA-12203: TNS:unable to connect to destination
.
The SQL statement being executed at the time of the error was: and was executed from the file .
/s_u01/<directories>/applmgr/<servername>/appl/alr/11.5.0/bin/ALECDC
Program exited with status 1
So what really was unable to get to the destination? Well on several concurrent manager nodes we were receiving these error messages:
Invalid option.
Usage: CONNECT <username> [AS SYSDBA|SYSOPER]
Invalid option.
Usage: CONNECT <username> [AS SYSDBA|SYSOPER]
unable to CONNECT to ORACLE after 3 attempts, exiting SQL*Plus
Failed to get arguments
ORACLE error 1012 in FDPCLS
Cause: FDPCLS failed due to ORA-01012: not logged on
The main COMPLETION_TEXT being returned was "Concurrent program returned no reason for failure." or "Program exited with status 1" or "Concurrent Manager encountered an error while running SQL*Plus for your concurrent request <ID>.
Review your concurrent request log and/or report output file for more detailed information."
Additionally, our Workflow Mailer went down with this error:
[Sep 24, 2013 7:12:24 PM MST]:1380075144128:Thread[outboundThreadGroup1,5,outboundThreadGroup]:0:-1:<CM node 1>:<IP>:-1:-1:UNEXPECTED:[SVC-GSM-WFMLRSVC-1893136-10006 : oracle.apps.fnd.wf.mailer.SMTPOutboundProcessor.open()]:Unable to connect to tranport
ERROR:
ORA-12203: TNS:unable to connect to destination
On a whole, most anything that needed to have a stable network connection from one point to another was disrupted so this aftermath made us take down the Concurrent Manager on both nodes and restart them to make sure everything was clean.
APP-FND-01564: ORACLE error 12203 in AFPCOA
Cause: AFPCOA failed due to ORA-12203: TNS:unable to connect to destination
.
The SQL statement being executed at the time of the error was: and was executed from the file .
/s_u01/<directories>/applmgr/<servername>/appl/alr/11.5.0/bin/ALECDC
Program exited with status 1
So what really was unable to get to the destination? Well on several concurrent manager nodes we were receiving these error messages:
Invalid option.
Usage: CONNECT <username> [AS SYSDBA|SYSOPER]
Invalid option.
Usage: CONNECT <username> [AS SYSDBA|SYSOPER]
unable to CONNECT to ORACLE after 3 attempts, exiting SQL*Plus
Failed to get arguments
ORACLE error 1012 in FDPCLS
Cause: FDPCLS failed due to ORA-01012: not logged on
The main COMPLETION_TEXT being returned was "Concurrent program returned no reason for failure." or "Program exited with status 1" or "Concurrent Manager encountered an error while running SQL*Plus for your concurrent request <ID>.
Review your concurrent request log and/or report output file for more detailed information."
Additionally, our Workflow Mailer went down with this error:
[Sep 24, 2013 7:12:24 PM MST]:1380075144128:Thread[outboundThreadGroup1,5,outboundThreadGroup]:0:-1:<CM node 1>:<IP>:-1:-1:UNEXPECTED:[SVC-GSM-WFMLRSVC-1893136-10006 : oracle.apps.fnd.wf.mailer.SMTPOutboundProcessor.open()]:Unable to connect to tranport
ERROR:
ORA-12203: TNS:unable to connect to destination
On a whole, most anything that needed to have a stable network connection from one point to another was disrupted so this aftermath made us take down the Concurrent Manager on both nodes and restart them to make sure everything was clean.
Tuesday, September 24, 2013
What happens when your Concurrent Manager goes crazy?
To answer the question I posed, I'll share with you a scenario we ran into a few months ago.
On a day like any other, at 11 AM we received an alert that we had created to tell us when users had queued up reports and their FND_USER records had become end dated. This was created as a result of the issue detailed here that we encountered after upgrading our database to 11.2.0.2 when we went to Exadata:
“Scheduled Requests Running for END_DATED Users 100% CPU and Giving ORA-01002 [ID 1080047.1]”
but the alert showed that the reports were Pending and the bug is obviously about Running reports right? So later in the day when the DBAs asked why Concurrency was so high, we really didn't think about these reports or the alert we received on them since the alert came in at 11 AM and the graph shows 5 AM.
At the time, I wanted to say that it was a problem maybe with the manager itself, with this nasty SQL behind the sql_id taking up the Concurrency time:
SELECT R.Conc_Login_Id, R.Request_Id, R.Phase_Code, R.Status_Code, P.Application_ID, P.Concurrent_Program_ID, P.Concurrent_Program_Name, R.Enable_Trace, R.Restart, DECODE(R.Increment_Dates, 'Y', 'Y', 'N'), R.NLS_Compliant, R.OUTPUT_FILE_TYPE, E.Executable_Name, E.Execution_File_Name, A2.Basepath, DECODE(R.Stale, 'Y', 'C', P.Execution_Method_Code), P.Print_Flag, P.Execution_Options, DECODE(P.Srs_Flag, 'Y', 'Y', 'Q', 'Y', 'N'), P.Argument_Method_Code, R.Print_Style, R.Argument_Input_Method_Code, R.Queue_Method_Code, R.Responsibility_ID, R.Responsibility_Application_ID, R.Requested_By, R.Number_Of_Copies, R.Save_Output_Flag, R.Printer, R.Print_Group, R.Priority, U.User_Name, O.Oracle_Username, O.Encrypted_Oracle_Password, R.Cd_Id, A.Basepath, A.Application_Short_Name, TO_CHAR(R.Requested_Start_Date,'YYYY/MM/DD HH24:MI:SS'), R.Nls_Language, R.Nls_Territory, DECODE(R.Parent_Request_ID, NULL, 0, R.Parent_Request_ID), R.Priority_Request_ID, R.Single_Thread_Flag, R.Has_Sub_Request, R.Is_Sub_Request, R.Req_Information, R.Description, R.Resubmit_Time, TO_CHAR(R.Resubmit_Interval), R.Resubmit_Interval_Type_Code, R.Resubmit_Interval_Unit_Code, TO_CHAR(R.Resubmit_End_Date,'YYYY/MM/DD HH24:MI:SS'), Decode(E.Execution_File_Name, NULL, 'N', Decode(E.Subroutine_Name, NULL, Decode(E.Execution_Method_Code, 'I', 'Y', 'J', 'Y', 'N'), 'Y')), R.Argument1, R.Argument2, R.Argument3, R.Argument4, R.Argument5, R.Argument6, R.Argument7, R.Argument8, R.Argument9, R.Argument10, R.Argument11, R.Argument12, R.Argument13, R.Argument14, R.Argument15, R.Argument16, R.Argument17, R.Argument18, R.Argument19, R.Argument20, R.Argument21, R.Argument22, R.Argument23, R.Argument24, R.Argument25, X.Argument26, X.Argument27, X.Argument28, X.Argument29, X.Argument30, X.Argument31, X.Argument32, X.Argument33, X.Argument34, X.Argument35, X.Argument36, X.Argument37, X.Argument38, X.Argument39, X.Argument40, X.Argument41, X.Argument42, X.Argument43, X.Argument44, X.Argument45, X.Argument46, X.Argument47, X.Argument48, X.Argument49, X.Argument50, X.Argument51, X.Argument52, X.Argument53, X.Argument54, X.Argument55, X.Argument56, X.Argument57, X.Argument58, X.Argument59, X.Argument60, X.Argument61, X.Argument62, X.Argument63, X.Argument64, X.Argument65, X.Argument66, X.Argument67, X.Argument68, X.Argument69, X.Argument70, X.Argument71, X.Argument72, X.Argument73, X.Argument74, X.Argument75, X.Argument76, X.Argument77, X.Argument78, X.Argument79, X.Argument80, X.Argument81, X.Argument82, X.Argument83, X.Argument84, X.Argument85, X.Argument86, X.Argument87, X.Argument88, X.Argument89, X.Argument90, X.Argument91, X.Argument92, X.Argument93, X.Argument94, X.Argument95, X.Argument96, X.Argument97, X.Argument98, X.Argument99, X.Argument100, R.number_of_arguments, C.CD_Name, NVL(R.Security_Group_ID, 0) FROM fnd_concurrent_requests R, fnd_concurrent_programs P, fnd_application A, fnd_user U, fnd_oracle_userid O, fnd_conflicts_domain C, fnd_concurrent_queues Q, fnd_application A2, fnd_executables E, fnd_conc_request_arguments X WHERE R.Status_code = 'I' And ((R.OPS_INSTANCE is null) or (R.OPS_INSTANCE = -1) or (R.OPS_INSTANCE = decode(:dcp_on,1,FND_CONC_GLOBAL.OPS_INST_NUM,R.OPS_INSTANCE))) And R.Request_ID = X.Request_ID(+) And R.Program_Application_Id = P.Application_Id(+) And R.Concurrent_Program_Id = P.Concurrent_Program_Id(+) And R.Program_Application_Id = A.Application_Id(+) And P.Executable_Application_Id = E.Application_Id(+) And P.Executable_Id = E.Executable_Id(+) And P.Executable_Application_Id = A2.Application_Id(+) And R.Requested_By = U.User_Id(+) And R.Cd_Id = C.Cd_Id(+) And R.Oracle_Id = O.Oracle_Id(+) And Q.Application_Id = :q_applid And Q.Concurrent_Queue_Id = :queue_id And (P.Enabled_Flag is NULL OR P.Enabled_Flag = 'Y') And R.Hold_Flag = 'N' And R.Requested_Start_Date <= Sysdate And ( R.Enforce_Seriality_Flag = 'N' OR ( C.RunAlone_Flag = P.Run_Alone_Flag And (P.Run_Alone_Flag = 'N' OR Not Exists (Select Null From Fnd_Concurrent_Requests Sr Where Sr.Status_Code In ('R', 'T') And Sr.Enforce_Seriality_Flag = 'Y' And Sr.CD_id = C.CD_Id)))) And Q.Running_Processes <= Q.Max_Processes And R.Rowid = :reqname And ((P.Execution_Method_Code != 'S' OR (R.PROGRAM_APPLICATION_ID,R.CONCURRENT_PROGRAM_ID) IN ((0,98),(0,100),(0,31721),(0,31722),(0,31757))) AND ((R.PROGRAM_APPLICATION_ID,R.CONCURRENT_PROGRAM_ID) NOT IN ((0,36888),(111,31715),(140,20445),(140,20810),(140,38315),(200,20532),(200,36067),(200,36068),(201,32439),(201,32460),(201,32469),(201,32844),(222,20865),(222,20893),(222,31738),(222,31893),(222,38640),(510,43959),(510,43960),(510,43966),(510,43967),(530,49102),(530,49106),(535,43927),(535,43928),(535,43929),(20004,31959),(20004,31961),(20004,31971),(20004,32058),(20004,33549),(20004,33625),(20004,41677),(20009,31993),(20009,32032),(20009,32164),(20009,32243),(20009,32250),(20009,32349),(20009,33564),(20009,33605),(20009,33679),(20009,33689),(20009,34482),(20009,34924),(20009,35325),(20009,35385),(20009,37049),(20009,43079),(20009,46390),(20009,56086),(20033,33685),(20033,39049),(20033,48498),(20033,48499),(20033,48518),(20033,48519),(20033,48539),(20033,48540),(20033,48558),(20033,48560),(20154,37533),(20154,37538),(20154,37909),(20154,39109),(20154,39169),(20154,39189),(20154,39457),(20154,39497),(20154,39517),(20154,39677),(20154,40377),(20154,40517),(20154,40537),(20154,40737),(20154,40818),(20154,41798),(20154,41857),(20154,41858),(20154,41897),(20154,42171),(20154,42173),(20154,42417),(20154,42697),(20154,42838),(20154,43039),(20154,43077),(20154,43297),(20154,43558),(20154,43777),(20154,43797),(20154,43877),(20154,45870),(20154,45872),(20154,45990),(20154,46070),(20154,46694),(20154,46695),(20154,46710),(20154,47030),(20154,47211),(20154,48418),(20154,50610),(20154,50611),(20154,50651),(20154,50880),(20154,50901),(20154,51141),(20154,51183),(20154,51242),(20154,51244),(20154,51323),(20154,51361),(20154,51463),(20154,51481),(20154,51801),(20154,51946),(20154,52383),(20154,52384),(20154,52385),(20154,52386),(20154,52388),(20154,53643),(20154,54063),(20154,54104),(20154,55482),(20154,55500),(20154,55881),(20154,55900),(20154,56360),(20154,56521),(20154,56930),(20154,56931),(20154,56932),(20154,56933),(20154,56934),(20154,56935),(20154,56936),(20154,56937),(20154,56938),(20154,56939),(20154,56940),(20154,56941),(20154,56942),(20154,56943),(20154,56944),(20154,56962),(20154,56963),(20154,57158),(20154,57159),(20154,57248),(20154,57284),(20154,57333),(20154,57334),(20154,57507),(20214,39804),(20214,39838),(20214,40937)) AND R.REQUESTED_BY NOT IN (20829,21465,192077))) FOR UPDATE OF R.status_code NoWait
Which looks like it is the actual manager locking (FOR UPDATE) the records when they were coming in ready to run the reports. Yet when I looked at the sessions, new sessions were popping in and out with recent logon_time values, all from applmgr on Concurrent Manager node 2 and many of the events are listed as “library cache: mutex X” (references here and here for articles I DID find that had some relevance). The next day, I decide to look at this from a different view point since what I had been doing was to query the DB to try and find what was holding a lock (with no success). That's when I decided to look closer at the OS on CM node 2, which was the only CM server showing as having locked processes, by doing a top command, and found that 4 different threads were trying to take 100% of the CPU below:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3165 applmgr 25 0 3069m 3.0g 2904 R 100.1 4.7 496:35.38 FNDLIBR
19021 applmgr 25 0 3069m 3.0g 2840 R 100.1 4.7 496:35.03 FNDLIBR
21783 applmgr 25 0 3068m 3.0g 2912 R 100.1 4.7 493:46.01 FNDLIBR
29837 applmgr 25 0 3068m 3.0g 2828 R 100.1 4.7 493:28.17 FNDLIBR
Using those PIDs, I then ran this command:
select * from fnd_concurrent_requests
where os_process_id = &OS_PID
What was odd is that each PID was giving me somewhere around 25-50 results when I was expecting a single row, until I realized that this corresponded to a dedicated concurrent manager process running in Financials. Going into the application, I went to the Administer Concurrent Manager form (FNDCPVCM) and looked for what CMs were being run by CM node 2 and found that Standard Manager was Active on that node. Clicking on this entry and then Processes presented me with all the processes (Active, Deactivated, or Terminated) where I noticed that the values under System looked an awful lot like our OS PIDs so I queried on one and low and behold a. it returned an Active process and b. the log file of the process showed that it was thrashing on a user with inactive responsibilities just like in the My Oracle Support note above. The error message was initially:
Cause: UPDATE_STATUS failed due to ORA-01002: fetch out of sequence.
and knowing it was related to an end_dated user I tried to extend the end date for the responsibilities by an extra day, but instead of making everything happy in CM land it just changed the error message being produced to:
Cause: UPDATE_STATUS failed due to ORA-01008: not all variables bound
with the SQL statement changing from FND_CONCURRENT_REQUESTS (which was in exclusive mode due to the FOR UPDATE part of the statement) to FND_USER. I don't know if this is because all 4 threads were still trying to hold all the server resources, and it would have returned normally after burning itself out on the statements it was going through, but this is where I deactivated the Standard Manager when there were no long running requests in the CM. Monitoring for a few minutes with no change, after all jobs Running had completed, I had to Terminate the CM because those threads were still showing as Active and were still taking up 100% of the CPU on the server. Once Terminated those 4 processes no longer showed as being Active and the thrashing which the DBA alerted us to, ceased to be. With the processes gone, I could now put the user requests which caused all of this On Hold so that the CM wouldn't find itself in the same old situation once we turned everything back on. I then Activated the Standard Manager, verified that no threads were hitting 100% on the CM node, and called it a job well done after I made sure the user still needed their reports after transitioning to another position in the company (which is why their account was end dated in the first place).
The moral of the story is that even though all the processes were Pending, so I thought there wasn't a problem, it appears the bug which we created this alert for affects the system not only when the request is Running and it can't finish but it also hits us when the system TRIES to run something and the user/responsibilities are end dated!
On a day like any other, at 11 AM we received an alert that we had created to tell us when users had queued up reports and their FND_USER records had become end dated. This was created as a result of the issue detailed here that we encountered after upgrading our database to 11.2.0.2 when we went to Exadata:
“Scheduled Requests Running for END_DATED Users 100% CPU and Giving ORA-01002 [ID 1080047.1]”
but the alert showed that the reports were Pending and the bug is obviously about Running reports right? So later in the day when the DBAs asked why Concurrency was so high, we really didn't think about these reports or the alert we received on them since the alert came in at 11 AM and the graph shows 5 AM.
At the time, I wanted to say that it was a problem maybe with the manager itself, with this nasty SQL behind the sql_id taking up the Concurrency time:
SELECT R.Conc_Login_Id, R.Request_Id, R.Phase_Code, R.Status_Code, P.Application_ID, P.Concurrent_Program_ID, P.Concurrent_Program_Name, R.Enable_Trace, R.Restart, DECODE(R.Increment_Dates, 'Y', 'Y', 'N'), R.NLS_Compliant, R.OUTPUT_FILE_TYPE, E.Executable_Name, E.Execution_File_Name, A2.Basepath, DECODE(R.Stale, 'Y', 'C', P.Execution_Method_Code), P.Print_Flag, P.Execution_Options, DECODE(P.Srs_Flag, 'Y', 'Y', 'Q', 'Y', 'N'), P.Argument_Method_Code, R.Print_Style, R.Argument_Input_Method_Code, R.Queue_Method_Code, R.Responsibility_ID, R.Responsibility_Application_ID, R.Requested_By, R.Number_Of_Copies, R.Save_Output_Flag, R.Printer, R.Print_Group, R.Priority, U.User_Name, O.Oracle_Username, O.Encrypted_Oracle_Password, R.Cd_Id, A.Basepath, A.Application_Short_Name, TO_CHAR(R.Requested_Start_Date,'YYYY/MM/DD HH24:MI:SS'), R.Nls_Language, R.Nls_Territory, DECODE(R.Parent_Request_ID, NULL, 0, R.Parent_Request_ID), R.Priority_Request_ID, R.Single_Thread_Flag, R.Has_Sub_Request, R.Is_Sub_Request, R.Req_Information, R.Description, R.Resubmit_Time, TO_CHAR(R.Resubmit_Interval), R.Resubmit_Interval_Type_Code, R.Resubmit_Interval_Unit_Code, TO_CHAR(R.Resubmit_End_Date,'YYYY/MM/DD HH24:MI:SS'), Decode(E.Execution_File_Name, NULL, 'N', Decode(E.Subroutine_Name, NULL, Decode(E.Execution_Method_Code, 'I', 'Y', 'J', 'Y', 'N'), 'Y')), R.Argument1, R.Argument2, R.Argument3, R.Argument4, R.Argument5, R.Argument6, R.Argument7, R.Argument8, R.Argument9, R.Argument10, R.Argument11, R.Argument12, R.Argument13, R.Argument14, R.Argument15, R.Argument16, R.Argument17, R.Argument18, R.Argument19, R.Argument20, R.Argument21, R.Argument22, R.Argument23, R.Argument24, R.Argument25, X.Argument26, X.Argument27, X.Argument28, X.Argument29, X.Argument30, X.Argument31, X.Argument32, X.Argument33, X.Argument34, X.Argument35, X.Argument36, X.Argument37, X.Argument38, X.Argument39, X.Argument40, X.Argument41, X.Argument42, X.Argument43, X.Argument44, X.Argument45, X.Argument46, X.Argument47, X.Argument48, X.Argument49, X.Argument50, X.Argument51, X.Argument52, X.Argument53, X.Argument54, X.Argument55, X.Argument56, X.Argument57, X.Argument58, X.Argument59, X.Argument60, X.Argument61, X.Argument62, X.Argument63, X.Argument64, X.Argument65, X.Argument66, X.Argument67, X.Argument68, X.Argument69, X.Argument70, X.Argument71, X.Argument72, X.Argument73, X.Argument74, X.Argument75, X.Argument76, X.Argument77, X.Argument78, X.Argument79, X.Argument80, X.Argument81, X.Argument82, X.Argument83, X.Argument84, X.Argument85, X.Argument86, X.Argument87, X.Argument88, X.Argument89, X.Argument90, X.Argument91, X.Argument92, X.Argument93, X.Argument94, X.Argument95, X.Argument96, X.Argument97, X.Argument98, X.Argument99, X.Argument100, R.number_of_arguments, C.CD_Name, NVL(R.Security_Group_ID, 0) FROM fnd_concurrent_requests R, fnd_concurrent_programs P, fnd_application A, fnd_user U, fnd_oracle_userid O, fnd_conflicts_domain C, fnd_concurrent_queues Q, fnd_application A2, fnd_executables E, fnd_conc_request_arguments X WHERE R.Status_code = 'I' And ((R.OPS_INSTANCE is null) or (R.OPS_INSTANCE = -1) or (R.OPS_INSTANCE = decode(:dcp_on,1,FND_CONC_GLOBAL.OPS_INST_NUM,R.OPS_INSTANCE))) And R.Request_ID = X.Request_ID(+) And R.Program_Application_Id = P.Application_Id(+) And R.Concurrent_Program_Id = P.Concurrent_Program_Id(+) And R.Program_Application_Id = A.Application_Id(+) And P.Executable_Application_Id = E.Application_Id(+) And P.Executable_Id = E.Executable_Id(+) And P.Executable_Application_Id = A2.Application_Id(+) And R.Requested_By = U.User_Id(+) And R.Cd_Id = C.Cd_Id(+) And R.Oracle_Id = O.Oracle_Id(+) And Q.Application_Id = :q_applid And Q.Concurrent_Queue_Id = :queue_id And (P.Enabled_Flag is NULL OR P.Enabled_Flag = 'Y') And R.Hold_Flag = 'N' And R.Requested_Start_Date <= Sysdate And ( R.Enforce_Seriality_Flag = 'N' OR ( C.RunAlone_Flag = P.Run_Alone_Flag And (P.Run_Alone_Flag = 'N' OR Not Exists (Select Null From Fnd_Concurrent_Requests Sr Where Sr.Status_Code In ('R', 'T') And Sr.Enforce_Seriality_Flag = 'Y' And Sr.CD_id = C.CD_Id)))) And Q.Running_Processes <= Q.Max_Processes And R.Rowid = :reqname And ((P.Execution_Method_Code != 'S' OR (R.PROGRAM_APPLICATION_ID,R.CONCURRENT_PROGRAM_ID) IN ((0,98),(0,100),(0,31721),(0,31722),(0,31757))) AND ((R.PROGRAM_APPLICATION_ID,R.CONCURRENT_PROGRAM_ID) NOT IN ((0,36888),(111,31715),(140,20445),(140,20810),(140,38315),(200,20532),(200,36067),(200,36068),(201,32439),(201,32460),(201,32469),(201,32844),(222,20865),(222,20893),(222,31738),(222,31893),(222,38640),(510,43959),(510,43960),(510,43966),(510,43967),(530,49102),(530,49106),(535,43927),(535,43928),(535,43929),(20004,31959),(20004,31961),(20004,31971),(20004,32058),(20004,33549),(20004,33625),(20004,41677),(20009,31993),(20009,32032),(20009,32164),(20009,32243),(20009,32250),(20009,32349),(20009,33564),(20009,33605),(20009,33679),(20009,33689),(20009,34482),(20009,34924),(20009,35325),(20009,35385),(20009,37049),(20009,43079),(20009,46390),(20009,56086),(20033,33685),(20033,39049),(20033,48498),(20033,48499),(20033,48518),(20033,48519),(20033,48539),(20033,48540),(20033,48558),(20033,48560),(20154,37533),(20154,37538),(20154,37909),(20154,39109),(20154,39169),(20154,39189),(20154,39457),(20154,39497),(20154,39517),(20154,39677),(20154,40377),(20154,40517),(20154,40537),(20154,40737),(20154,40818),(20154,41798),(20154,41857),(20154,41858),(20154,41897),(20154,42171),(20154,42173),(20154,42417),(20154,42697),(20154,42838),(20154,43039),(20154,43077),(20154,43297),(20154,43558),(20154,43777),(20154,43797),(20154,43877),(20154,45870),(20154,45872),(20154,45990),(20154,46070),(20154,46694),(20154,46695),(20154,46710),(20154,47030),(20154,47211),(20154,48418),(20154,50610),(20154,50611),(20154,50651),(20154,50880),(20154,50901),(20154,51141),(20154,51183),(20154,51242),(20154,51244),(20154,51323),(20154,51361),(20154,51463),(20154,51481),(20154,51801),(20154,51946),(20154,52383),(20154,52384),(20154,52385),(20154,52386),(20154,52388),(20154,53643),(20154,54063),(20154,54104),(20154,55482),(20154,55500),(20154,55881),(20154,55900),(20154,56360),(20154,56521),(20154,56930),(20154,56931),(20154,56932),(20154,56933),(20154,56934),(20154,56935),(20154,56936),(20154,56937),(20154,56938),(20154,56939),(20154,56940),(20154,56941),(20154,56942),(20154,56943),(20154,56944),(20154,56962),(20154,56963),(20154,57158),(20154,57159),(20154,57248),(20154,57284),(20154,57333),(20154,57334),(20154,57507),(20214,39804),(20214,39838),(20214,40937)) AND R.REQUESTED_BY NOT IN (20829,21465,192077))) FOR UPDATE OF R.status_code NoWait
Which looks like it is the actual manager locking (FOR UPDATE) the records when they were coming in ready to run the reports. Yet when I looked at the sessions, new sessions were popping in and out with recent logon_time values, all from applmgr on Concurrent Manager node 2 and many of the events are listed as “library cache: mutex X” (references here and here for articles I DID find that had some relevance). The next day, I decide to look at this from a different view point since what I had been doing was to query the DB to try and find what was holding a lock (with no success). That's when I decided to look closer at the OS on CM node 2, which was the only CM server showing as having locked processes, by doing a top command, and found that 4 different threads were trying to take 100% of the CPU below:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3165 applmgr 25 0 3069m 3.0g 2904 R 100.1 4.7 496:35.38 FNDLIBR
19021 applmgr 25 0 3069m 3.0g 2840 R 100.1 4.7 496:35.03 FNDLIBR
21783 applmgr 25 0 3068m 3.0g 2912 R 100.1 4.7 493:46.01 FNDLIBR
29837 applmgr 25 0 3068m 3.0g 2828 R 100.1 4.7 493:28.17 FNDLIBR
Using those PIDs, I then ran this command:
select * from fnd_concurrent_requests
where os_process_id = &OS_PID
What was odd is that each PID was giving me somewhere around 25-50 results when I was expecting a single row, until I realized that this corresponded to a dedicated concurrent manager process running in Financials. Going into the application, I went to the Administer Concurrent Manager form (FNDCPVCM) and looked for what CMs were being run by CM node 2 and found that Standard Manager was Active on that node. Clicking on this entry and then Processes presented me with all the processes (Active, Deactivated, or Terminated) where I noticed that the values under System looked an awful lot like our OS PIDs so I queried on one and low and behold a. it returned an Active process and b. the log file of the process showed that it was thrashing on a user with inactive responsibilities just like in the My Oracle Support note above. The error message was initially:
Cause: UPDATE_STATUS failed due to ORA-01002: fetch out of sequence.
and knowing it was related to an end_dated user I tried to extend the end date for the responsibilities by an extra day, but instead of making everything happy in CM land it just changed the error message being produced to:
Cause: UPDATE_STATUS failed due to ORA-01008: not all variables bound
with the SQL statement changing from FND_CONCURRENT_REQUESTS (which was in exclusive mode due to the FOR UPDATE part of the statement) to FND_USER. I don't know if this is because all 4 threads were still trying to hold all the server resources, and it would have returned normally after burning itself out on the statements it was going through, but this is where I deactivated the Standard Manager when there were no long running requests in the CM. Monitoring for a few minutes with no change, after all jobs Running had completed, I had to Terminate the CM because those threads were still showing as Active and were still taking up 100% of the CPU on the server. Once Terminated those 4 processes no longer showed as being Active and the thrashing which the DBA alerted us to, ceased to be. With the processes gone, I could now put the user requests which caused all of this On Hold so that the CM wouldn't find itself in the same old situation once we turned everything back on. I then Activated the Standard Manager, verified that no threads were hitting 100% on the CM node, and called it a job well done after I made sure the user still needed their reports after transitioning to another position in the company (which is why their account was end dated in the first place).
The moral of the story is that even though all the processes were Pending, so I thought there wasn't a problem, it appears the bug which we created this alert for affects the system not only when the request is Running and it can't finish but it also hits us when the system TRIES to run something and the user/responsibilities are end dated!
Thursday, August 8, 2013
Concurrent Manager bottleneck
A continuation of a yesterday's post, we had several "overnight" reports that normally started anywhere between 7 PM and 3 AM actually wait until 4 AM to start running in the Concurrent Manager. I was even alerted on our on-call phone about a backlog between 3-4 AM on one day, but I figured it was something to do with our user's requests that had been sitting there for a few days and that after cancelling them I assumed the issue would resolve itself.
Good news? It did, but I was still curious about the why of it so I looked at Autoinvoice Import Program reports, which should have kicked off but didn’t, until I ran into the same report scheduled by a user after 4 PM which didn’t kick off until after 4 AM. Very curious right? Why would the system just stop for 12 hours? Suddenly it hit me. What did the work shifts look like for the Standard Manager (assuming that’s where they went, and not Quick Manager)?
Our user in question had 7 of 10 slots in the Standard Manager with his stuck reports running before 4 PM and once the shift changed on the first night the process maximum was 7, which didn’t let anything else actually run the following morning until another shift change at 4 AM! Then later on the second night he had 8 of 10 slots before 4 PM, and again after the shift change nothing was able to process on the third morning until another shift change but that night was a different story because we had his reports complete during the day so there was no lingering backlog to stop up the managers the next morning.
As a byproduct of allowing user reports to sit running for too long, we identified a bottleneck in our system since usually the only time you bother looking at your Concurrent Manager setting is when you have a problem right? If the system has run for years, and nothing is wrong, you won't go looking for problems since there are none reported! I find it really interesting that this shift setup is almost completely backwards from our bigger EBS platform where we let the Concurrent Managers ramp up at night until we throttle them back when we have more of a user load on the system, but here we throttle it back at night and then ramp up the processes when the users are in the system. Maybe this group of users is more report intensive, but I doubt it so off on the hunt for details and a good long term solution I go! (Sure I can just change the processes here so we avoid that kind of bottleneck in the future, but is that really a solution?)
Good news? It did, but I was still curious about the why of it so I looked at Autoinvoice Import Program reports, which should have kicked off but didn’t, until I ran into the same report scheduled by a user after 4 PM which didn’t kick off until after 4 AM. Very curious right? Why would the system just stop for 12 hours? Suddenly it hit me. What did the work shifts look like for the Standard Manager (assuming that’s where they went, and not Quick Manager)?
Our user in question had 7 of 10 slots in the Standard Manager with his stuck reports running before 4 PM and once the shift changed on the first night the process maximum was 7, which didn’t let anything else actually run the following morning until another shift change at 4 AM! Then later on the second night he had 8 of 10 slots before 4 PM, and again after the shift change nothing was able to process on the third morning until another shift change but that night was a different story because we had his reports complete during the day so there was no lingering backlog to stop up the managers the next morning.
As a byproduct of allowing user reports to sit running for too long, we identified a bottleneck in our system since usually the only time you bother looking at your Concurrent Manager setting is when you have a problem right? If the system has run for years, and nothing is wrong, you won't go looking for problems since there are none reported! I find it really interesting that this shift setup is almost completely backwards from our bigger EBS platform where we let the Concurrent Managers ramp up at night until we throttle them back when we have more of a user load on the system, but here we throttle it back at night and then ramp up the processes when the users are in the system. Maybe this group of users is more report intensive, but I doubt it so off on the hunt for details and a good long term solution I go! (Sure I can just change the processes here so we avoid that kind of bottleneck in the future, but is that really a solution?)
Saturday, July 27, 2013
Where Should EBS Concurrent Managers be Located?
This article is chock full of goodness in our next spotlight of Steven Chan's EBS blog! This is particularly interesting to hear that it seems like there are several different ideas about the best way to complete this, even if technology has advanced to make some of those options no longer relevant.
Outside of what is listed in the title of the article, if you follow the link in the article, you'll find four MORE potential problems you could encounter with your EBS installation. More information is good information!
Outside of what is listed in the title of the article, if you follow the link in the article, you'll find four MORE potential problems you could encounter with your EBS installation. More information is good information!
Thursday, May 23, 2013
Concurrent Manager holding lock on a report
For some reason, we had a report which was locked up with “Could not reserve record x tries” so you couldn't View Details or Hold Request and even running a script to change the HOLD_FLAG was just hanging out. Looking at gv$session, the user didn't have any sessions which would've lead me to believe they had this locked up so I ran my handy dandy Exadata lock script to find the session holding my script up. The session had nothing for MODULE or ACTION, but the CLIENT_INFO "0 0 " looked familiar so I bounced the Conflict Resolution Manager without any changes happening. I started looking closer, as the report was sitting in the Quick Manager so I issued a Deactivate which took it down to only 1 Actual process and a Target of 0 but it just kept sitting there. Looking at the log files via Processes showed just one thread Active but when I clicked on Manager Log I received this error message:
APP-FND-01632: Cannot open file <directory>/w<process ID?>.mgr for reading
Cause: [Routine] encountered an error when attempting to open file <directory>/w<process ID?>.mgr for reading.
Action: Verify that the filename is correct, the environment variables controlling that filename are correct, and the file exists.
Action: Verify that protections on that file permit reading by this program.
Knowing that there was a problem with this thread, I then issued a Terminate for the Quick Manager and once it was completed with the Actual/Target both at 0 my script finally finished running as it no longer was encountering the locking condition. After committing my script, so the report was now Inactive/On Hold rather than Inactive/No Manager, I did an Activate for the Quick Manager and once it was back up I removed the hold on the report. It ran to completion in 2 seconds.
Now there are obviously some questions I have about this, as to why the manager thread had just locked up when it tried to pick up or start running the request, or if the string of numbers in the file name is actually a process ID which I can then backtrack later and give you more information in a later posting.
APP-FND-01632: Cannot open file <directory>/w<process ID?>.mgr for reading
Cause: [Routine] encountered an error when attempting to open file <directory>/w<process ID?>.mgr for reading.
Action: Verify that the filename is correct, the environment variables controlling that filename are correct, and the file exists.
Action: Verify that protections on that file permit reading by this program.
Knowing that there was a problem with this thread, I then issued a Terminate for the Quick Manager and once it was completed with the Actual/Target both at 0 my script finally finished running as it no longer was encountering the locking condition. After committing my script, so the report was now Inactive/On Hold rather than Inactive/No Manager, I did an Activate for the Quick Manager and once it was back up I removed the hold on the report. It ran to completion in 2 seconds.
Now there are obviously some questions I have about this, as to why the manager thread had just locked up when it tried to pick up or start running the request, or if the string of numbers in the file name is actually a process ID which I can then backtrack later and give you more information in a later posting.
Monday, May 6, 2013
ICM will mark this request as completed, will it?
From time to time, when trying to access concurrent requests you can be presented with this error message:
Request [ID] can no longer be cancelled. The Concurrent Manager process that was running this request has exited abnormally. The ICM will mark this request as completed with error.
That would be fine if it actually happened, but the problem is that I've seen this error message on many different EBS, Tech Stack and database versions over seven years and I've never actually seen the ICM mark the request in any way when the request gets into this state. There are 2 ways that I know how to resolve this. One, go into Help -> Diagnostics -> Examine (if you have this available) and change the fields PHASE_CODE to C and the STATUS CODE to X in two separate "transactions", Ctrl-S to save the record and when you refresh the form the request should show as Completed/Terminated. The other way is much more simple, where you write a script to update the same columns for the request in fnd_concurrent_requests as such:
update fnd_concurrent_requests
set phase_code = 'C', status_code = 'X'
where request_id = [ID]
Request [ID] can no longer be cancelled. The Concurrent Manager process that was running this request has exited abnormally. The ICM will mark this request as completed with error.
That would be fine if it actually happened, but the problem is that I've seen this error message on many different EBS, Tech Stack and database versions over seven years and I've never actually seen the ICM mark the request in any way when the request gets into this state. There are 2 ways that I know how to resolve this. One, go into Help -> Diagnostics -> Examine (if you have this available) and change the fields PHASE_CODE to C and the STATUS CODE to X in two separate "transactions", Ctrl-S to save the record and when you refresh the form the request should show as Completed/Terminated. The other way is much more simple, where you write a script to update the same columns for the request in fnd_concurrent_requests as such:
update fnd_concurrent_requests
set phase_code = 'C', status_code = 'X'
where request_id = [ID]
Thursday, March 14, 2013
Lazarus reports
Once upon a time, I thought that after a report had run in the Concurrent Manager there was no possible way to run the same request over again. Time has passed and I have become more powerful than you can possibly imagine, so I now know that the concurrent is just a program reading the values from tables within the data structure. This meant that it was possible to have reports emerge from the dead like Lazarus (or the Pit of the same name) with this script for 10.2.0.4 on EBS 11.5.10.2:
update fnd_concurrent_requests
set phase_code = 'P', status_code ='Q'
where request_id in ()
After going to 11.2.0.2 without changing from EBS 11.5.10.2, I noticed that my old script wouldn't exactly work the same so after several different investigative attempts the script needed to be tweaked to:
update fnd_concurrent_requests
set phase_code = 'P', status_code ='I'
where request_id in ()
Obviously something like this should be used with care, as restarting certain reports may cause data corruption issues, but if you're reading this blog you should be a responsible adult. Any irresponsible adults reading, please feel free to keep reading the blog. :}
Friday, February 1, 2013
Purging concurrent and Fixed Assets
If you have a realitively large application, you probably purge your concurrent request tables fairly frequently due to space limitations which most of the time is a benefit but I've recently found a reason that this can hurt you as well. With the Fixed Assets module, the table fa_book_controls keeps track of the depreciation runs that the system or the users run and if many deprecation runs are being with some frequency there doesn't appear to be any issues. The problem lies with infrequent deprecation runs when the last run happens and ends in error leaving the request_id populated in the table, and is subsequently then purged out of the tables by your regular concurrent purge processes. By having this mass_request_id in the table, when either the Calculate Gains and Losses or Depreciation Run concurrent reports are run they will error out barking about how they can't find the previous request:
APP-OFA-48392: Unable to get the concurrent request status using procedure FND_CONCURRENT.GET_REQUEST_STATUS.
This doesn't sound too dire, but if your business is in the midde of trying to close their books and this crops up you need to be able to resolve the issue quickly. Having encountered this situation several times, I've created the alert below to notify us if these conditions exist:
select mass_request_id, book_type_code
into &REQ_ID, &BOOK
from fa_book_controls
where mass_request_id is not null
and last_update_date < sysdate - (2/24)
The reason I am looking for a last_update_date greater than the past 2 hours is because this means the request has errored within the past few hours and while it is potentially a problem a few days from now this alert is giving us some lead time in fixing the issue.
APP-OFA-48392: Unable to get the concurrent request status using procedure FND_CONCURRENT.GET_REQUEST_STATUS.
This doesn't sound too dire, but if your business is in the midde of trying to close their books and this crops up you need to be able to resolve the issue quickly. Having encountered this situation several times, I've created the alert below to notify us if these conditions exist:
select mass_request_id, book_type_code
into &REQ_ID, &BOOK
from fa_book_controls
where mass_request_id is not null
and last_update_date < sysdate - (2/24)
The reason I am looking for a last_update_date greater than the past 2 hours is because this means the request has errored within the past few hours and while it is potentially a problem a few days from now this alert is giving us some lead time in fixing the issue.
Thursday, August 16, 2012
Concurrent:Active Request Limit (or how I finally learned to know what my system was saying)
The other day I saw a few jobs queuing in the Conflict Resolution Manager, and investigating I saw the following message:
This request is pending because the profile option 'Concurrent:Active Request Limit' is set.
This profile option controls how many requests a given user may have running at one time.
User X submitted this request on 09-AUG-2012 08:00:00.
The Conflict Resolution Manager will release this request when the number of running requests for this user is less than the maximum allowed by the profile option.
Now I’d seen this quite a few times but I always thought it was a bug and the CRM thought we couldn’t let anything run, since I interrepted it as being set at a user level, yet today when I looked at the message I wondered if we had it set at a site level and sure enough we did. It is entirely possible that with the old server hardware we were on a few years ago there was a reason this was setup but since it doesn't even look like we're hitting this limit I don’t think we need it set in our environment today since requests appear to be slowed down by this.
This request is pending because the profile option 'Concurrent:Active Request Limit' is set.
This profile option controls how many requests a given user may have running at one time.
User X submitted this request on 09-AUG-2012 08:00:00.
The Conflict Resolution Manager will release this request when the number of running requests for this user is less than the maximum allowed by the profile option.
Now I’d seen this quite a few times but I always thought it was a bug and the CRM thought we couldn’t let anything run, since I interrepted it as being set at a user level, yet today when I looked at the message I wondered if we had it set at a site level and sure enough we did. It is entirely possible that with the old server hardware we were on a few years ago there was a reason this was setup but since it doesn't even look like we're hitting this limit I don’t think we need it set in our environment today since requests appear to be slowed down by this.
Subscribe to:
Posts (Atom)