Print process deadlock

[Former Member]

Hi All,

<br/>

<br/>We are now facing some problems on our smartform printing programs, sometimes some of the smartform programs look getting stuck, from SM50, the processing time is endless, and from the detailed tracing log, there are repeated messages like below for every ONE MINUTE:

<br/>I WARNING: MtxLock 0x70000000636197c rrol0046 owner=33 deadlock ?

<br/>

<br/>I've searched the forum and also did google and SAP notes but can not get useful information match with my error, so could anyone please help to analyse what exact cause of this problem? Any suggestions is highly appreciated.

<br/>

<br/>The smartform program itself is simple and correct, just has one header and several items and uses normal SSF_FUNCTION_MODULE_NAME and CALL FNAME to do the print work, in most of time it works correct, but sometimes it just has problem and then the deadlock error occurred. I guess maybe it's because user tried to print too fast than the capability of the printer and then user canceled the job, then in some situations, the upcoming printing jobs get blocked and then get stuck, but it's just a guess, i've no proof to identify it.

<br/>

<br/>Here I attached the full trace log, hope someone could give me a idea, thank you very much!

<br/>

<br/>----

---

<br/>trc file: "dev_w38", trc level: 1, release: "701"

<br/>----

---

<br/>M Thu Dec 9 14:03:55 2010

<br/>M db_connect o.k.

<br/>M ICT: exclude compression: .zip,.cs,.rar,.arj,.z,.gz,.tar,.lzh,.cab,.hqx,.ace,.jar,.ear,.war,.css,.pdf,.js,.gzip

<br/>I MtxInit: 38 0 0

<br/>M SHM_PRES_BUF (addr: 0x700001050000000, size: 44000000)

<br/>M SHM_ROLL_AREA (addr: 0x700001060000000, size: 536870912)

<br/>M SHM_PAGING_AREA (addr: 0x700001080000000, size: 536870912)

<br/>M SHM_ROLL_ADM (addr: 0x700000006221000, size: 5506336)

<br/>M SHM_PAGING_ADM (addr: 0x7000010a0000000, size: 1311776)

<br/>M ThCreateNoBuffer allocated 544152 bytes for 1000 entries at 0x7000010b0002000

<br/>M ThCreateNoBuffer index size: 3000 elems

<br/>M ThCreateVBAdm allocated 11776 bytes (50 server) at 0x7000010d0000000

<br/>X EmInit: MmSetImplementation( 2 ).

<br/>X MM global diagnostic options set: 0

<br/>X EM/TOTAL_SIZE_MB = 262144

<br/>X mm.dump: set maximum dump mem to 96 MB

<br/>M Deactivate statistics hyper index locking

<br/>I *** INFO Shm 44 in Pool 40 18928 KB estimated 14500 KB real ( -4427 KB -24 %)

<br/>I *** INFO Shm 45 in Pool 40 12928 KB estimated 8500 KB real ( -4427 KB -35 %)

<br/>B dbntab: NTAB buffers attached

<br/>B dbntab: Buffer FTAB(hash header) (addr: 0x7000010b0088088, size: 584)

<br/>B dbntab: Buffer FTAB(anchor array) (addr: 0x7000010b00882d0, size: 1280008)

<br/>B dbntab: Buffer FTAB(item array) (addr: 0x7000010b01c0ad8, size: 5120000)

<br/>B dbntab: Buffer FTAB(data area) (addr: 0x7000010b06a2ad8, size: 122880000)

<br/>B dbntab: Buffer IREC(hash header) (addr: 0x7000010b7bd4088, size: 584)

<br/>B dbntab: Buffer IREC(anchor array) (addr: 0x7000010b7bd42d0, size: 1280008)

<br/>B dbntab: Buffer IREC(item array) (addr: 0x7000010b7d0cad8, size: 1280000)

<br/>B dbntab: Buffer IREC(data area) (addr: 0x7000010b7e452d8, size: 12288000)

<br/>B dbntab: Buffer STAB(hash header) (addr: 0x7000010b89ff088, size: 584)

<br/>B dbntab: Buffer STAB(anchor array) (addr: 0x7000010b89ff2d0, size: 1280008)

<br/>B dbntab: Buffer STAB(item array) (addr: 0x7000010b8b37ad8, size: 1280000)

<br/>B dbntab: Buffer STAB(data area) (addr: 0x7000010b8c702d8, size: 6144000)

<br/>B dbntab: Buffer TTAB(hash header) (addr: 0x7000010b924e088, size: 6720)

<br/>B dbntab: Buffer TTAB(anchor array) (addr: 0x7000010b924fac8, size: 1280008)

<br/>B dbntab: Buffer TTAB(item array) (addr: 0x7000010b93882d0, size: 3200000)

<br/>B dbntab: Buffer TTAB(data area) (addr: 0x7000010b96956d0, size: 23360000)

<br/>B db_con_shm_ini: WP_ID = 38, WP_CNT = 59, CON_ID = -1

<br/>B dbstat: TABSTAT buffer attached (addr: 0x7000010f002d2d0)

<br/>B dbtbxbuf: Buffer TABL (addr: 0x700001100000100, size: 180000000, end: 0x70000110aba9600)

<br/>B dbtbxbuf: Buffer TABLP (addr: 0x700000006763100, size: 20480000, end: 0x700000007aeb100)

<br/>B dbexpbuf: Buffer EIBUF (addr: 0x700000007aec108, size: 67108864, end: 0x70000000baec108)

<br/>B dbexpbuf: Buffer ESM (addr: 0x700001110000108, size: 4194304, end: 0x700001110400108)

<br/>B dbexpbuf: Buffer CUA (addr: 0x7000010bace2108, size: 18432000, end: 0x7000010bbe76108)

<br/>B dbexpbuf: Buffer OTR (addr: 0x700001120000108, size: 4194304, end: 0x700001120400108)

<br/>B dbcalbuf: Buffer CALE (addr: 0x70000000baee000, size: 500000, end: 0x70000000bb68120)

<br/>M CCMS: AlInitGlobals : alert/use_sema_lock = TRUE.

<br/>S *** init spool environment

<br/>S TSPEVJOB updates inside critical section: event_update_nocsec = 0

<br/>S initialize debug system

<br/>T Stack direction is downwards.

<br/>T debug control: prepare exclude for printer trace

<br/>T new memory block 0x114388060

<br/>S spool kernel/ddic check: Ok

<br/>S using table TSP02FX for frontend printing

<br/>S 1 spool work process(es) found

<br/>S frontend print via spool service enabled

<br/>S printer list size is 150

<br/>S printer type list size is 50

<br/>S queue size (profile) = 300

<br/>S hostspool list size = 3000

<br/>S option list size is 30

<br/>I *** INFO Shm 49 in Pool 40 2898 KB estimated 1632 KB real ( -1266 KB -44 %)

<br/>S found processing queue enabled

<br/>S found spool memory service RSPO-RCLOCKS at 0x7000010bbe77070

<br/>S doing lock recovery

<br/>S setting server cache root

<br/>S found spool memory service RSPO-SERVERCACHE at 0x7000010bbe78160

<br/>S using messages for server info

<br/>S size of spec char cache entry: 297032 bytes (timeout 100 sec)

<br/>S size of open spool request entry: 2512 bytes

<br/>S immediate print option for implicitely closed spool requests is disabled

<br/>A **GENER Trace switched on ***

<br/>A

<br/>A -PXA--

---

<br/>A PXA INITIALIZATION

<br/>A PXA: Locked PXA-Semaphore.

<br/>A System page size: 4kb, total admin_size: 237304kb, dir_size: 58960kb.

<br/>A Attached to PXA (address 0x700001130000000, size 3000000K, 4 fragments of 690676K )

<br/>A

<br/>A Thu Dec 9 14:03:59 2010

<br/>A abap/pxa = shared unprotect gen_remote

<br/>A PXA INITIALIZATION FINISHED

<br/>A -PXA--

---

<br/>A

<br/>A ABAP ShmAdm attached (addr=0x700000f4046c000 leng=20955136 end=0x700000f41868000)

<br/>A >> Shm MMADM area (addr=0x700000f40915418 leng=247168 end=0x700000f40951998)

<br/>A >> Shm MMDAT area (addr=0x700000f40952000 leng=15818752 end=0x700000f41868000)

<br/>A RFC rfc/signon_error_log = -1

<br/>A RFC rfc/dump_connection_info = 0

<br/>A RFC rfc/dump_client_info = 0

<br/>A RFC rfc/cp_convert/ignore_error = 1

<br/>A RFC rfc/cp_convert/conversion_char = 23

<br/>A RFC rfc/wan_compress/threshold = 251

<br/>A RFC rfc/recorder_pcs not set, use defaule value: 2

<br/>A RFC rfc/delta_trc_level not set, use default value: 0

<br/>A RFC rfc/no_uuid_check not set, use default value: 0

<br/>A RFC rfc/bc_ignore_thcmaccp_retcode not set, use default value: 0

<br/>A RFC Method> initialize RemObjDriver for ABAP Objects

<br/>M ThrCreateShObjects allocated 122630 bytes at 0x70000000c124000

<br/>N SsfSapSecin: putenv(SECUDIR=/usr/sap/PRD/DVEBMGS00/sec): ok

<br/>N

<br/>N =================================================

<br/>N === SSF INITIALIZATION:

<br/>N ===...SSF Security Toolkit name SAPSECULIB .

<br/>N ===...SSF library is /usr/sap/PRD/DVEBMGS00/exe/libsapcrypto.o .

<br/>N ===...SSF default hash algorithm is SHA1 .

<br/>N ===...SSF default symmetric encryption algorithm is DES-CBC .

<br/>N ===...SECUDIR="/usr/sap/PRD/DVEBMGS00/sec"

<br/>N ===...loading of Security Toolkit successfully completed.

<br/>N === SAPCRYPTOLIB 5.5.5C pl29 (Jan 30 2010) MT-safe

<br/>N =================================================

<br/>N MskiInitLogonTicketCacheHandle: Logon Ticket cache pointer retrieved from shared memory.

<br/>N MskiInitLogonTicketCacheHandle: Workprocess runs with Logon Ticket cache.

<br/>M JrfcVmcRegisterNativesDriver o.k.

<br/>W =================================================

<br/>W === ipl_Init() called

<br/>B dbtran INFO (init_connection '<DEFAULT>' [ORACLE:700.08]):

<br/>B max_blocking_factor = 5, max_in_blocking_factor = 5,

<br/>B min_blocking_factor = 5, min_in_blocking_factor = 5,

<br/>B prefer_union_all = 0, prefer_join = 0,

<br/>B prefer_fix_blocking = 0, prefer_in_itab_opt = 1,

<br/>B convert AVG = 0, alias table FUPD = 0,

<br/>B escape_as_literal = 1, opt GE LE to BETWEEN = 0,

<br/>B select * =0x0f, character encoding = STD / <none>:-,

<br/>B use_hints = abap->1, dbif->0x1, upto->2147483647, rule_in->0,

<br/>B rule_fae->0, concat_fae->0, concat_fae_or->0

<br/>W ITS Plugin: Path dw_gui

<br/>W ITS Plugin: Description ITS Plugin - ITS rendering DLL

<br/>W ITS Plugin: sizeof(SAP_UC) 2

<br/>W ITS Plugin: Release: 701, [7010.0.97.20020600]

<br/>W ITS Plugin: Int.version, [33]

<br/>W ITS Plugin: Feature set: [22]

<br/>W ===... Calling itsp_Init in external dll ===>

<br/>W PpioRecoverLocks, table: 0x700000f418f2778

<br/>W PpioRecoverLocks, number of file locks 256

<br/>W PpioRecoverLocks: file lock set to: (nil)

<br/>W PpioRecoverLocks: directory lock set to: (nil)

<br/>W PpioRecoverLocks: global lock set to: (nil)

<br/>W PpioRecoverLocks() done

<br/>W PprcRecoverLocks, table: 0x700000f418f27e8

<br/>W PprcRecoverLocks: directory lock set to: (nil)

<br/>W PprcRecoverLocks() done

<br/>W === ipl_Init() returns 0, ITSPE_OK: OK

<br/>W =================================================

<br/>N VSI: WP init in ABAP VM completed with rc=0

<br/>E Profile-Parameter: enque/deque_wait_answer = FALSE

<br/>E Profile-Parameter: enque/sync_dequeall = 0

<br/>E EnqId_SuppressIpc: local EnqId initialization o.k.

<br/>E EnqCcInitialize: local enqueue client init o.k.

<br/>M ThCheckPrevUser: previous user was T78/M0, clean counter 0

<br/>M ThCheckPrevUser: clean previous user T78/U26013/M0/I2/V-1

<br/>M

<br/>M Modeinfo for User T78/M0

<br/>M

<br/>M tm state = 4

<br/>M uid = 26013

<br/>M term type = 0x4

<br/>M display = 0x8

<br/>M cpic_no = 0

<br/>M cpic_idx = -1

<br/>M usr = >8000199 <

<br/>M terminal = >ceegsap20 <

<br/>M client = >800<

<br/>M conversation_ID = > <

<br/>M appc_tm_conv_idx = -1

<br/>M its_plugin = NO

<br/>M allowCreateMode = YES

<br/>M wp_ca block = -1

<br/>M appc_ca block = -1

<br/>M blockSoftCanel = NO

<br/>M session_id = >4CFF77CE4A6A0068E10080000A04C87E<

<br/>M ext_session_id = >4CFF77CE4A6A0068E10080000A04C87E<

<br/>M imode = 2

<br/>M mode state = 0x1a

<br/>M mode clean_state = 2

<br/>M task_type = ZTTADIA

<br/>M lastThFc = THFCTERM

<br/>M lastAction = TH_IACT_NO_ACTION

<br/>M th_errno = 0

<br/>M rollout_reason = 1

<br/>M last_rollout_level = 7

<br/>M async_receives = 0

<br/>M cpic_receive = 0

<br/>M em handle = 67

<br/>M roll state = 3

<br/>M abap state = 3

<br/>M em state = 2

<br/>M eg state = 1

<br/>M spa state = 3

<br/>M enq state = 0

<br/>M softcancel = 1

<br/>M cancelInitiator = DISPATCHER

<br/>M clean_state = DP_SOFTCANCEL

<br/>M next hook = T-1/U-1/M255

<br/>M master hook = T-1/U-1/M255

<br/>M slave hook = T-1/U-1/M255

<br/>M debug_tid = 255

<br/>M debug_mode = 0

<br/>M mode type = 0x1

<br/>M debug = 0

<br/>M msg_count = 6

<br/>M tcode = >ZPP015 <

<br/>M last_wp = 38

<br/>M client conversation_ID = > <

<br/>M server conversation_ID = > <

<br/>M lock = 0

<br/>M max enq infos = 0

<br/>M act enq infos = 0

<br/>M em_hyper_hdl = 0x700000f41d918e8

<br/>M plugin_info = NULL

<br/>M act_plugin_hdl = -1

<br/>M act_plugin_no = 0

<br/>M max_plugin_no = 0

<br/>M

<br/>M ThCheckPrevUser: reset spa state for user T78/U26013/M0

<br/>M ThSetDoSafeCleanup: th_do_safe_cleanup = FALSE (wanted FALSE)

<br/>M LOCK WP ca_blk 44

<br/>M ThAtWpBlk: set zttatiln to zero

<br/>M ThAtWpBlk: set zttatoln to zero

<br/>M DpVmcGetVmByTmAdm: no VM found for T78/M0/I2

<br/>M LOCK APPC ca_blk 640

<br/>M set task type ZTTADIA

<br/>M ThCleanPrevUser: clean U26013 T78 M0 I2 no VM clean state DP_SOFTCANCEL clean counter 1

<br/>M ThCleanPrevUser: saved MODE_REC = 10

<br/>M PfStatDisconnect: disconnect statistics

<br/>M ThCleanPrevUser: found soft cancel flag

<br/>M ThSoftCancel: set clean state of T78/M0 to DP_DEFAULT_CLEANING

<br/>M ThSoftCancel session in state TM_DISCONNECTED, delete mode

<br/>M ThIAMDel: delete tid/mode 78/0 (th_errno 47, release 1)

<br/>M ThIDeleteMode (78, 0, 3, ><, 0, 255, TRUE)

<br/>M ThIDeleteMode: no modes found ..

<br/>M no sub modes

<br/>M ThCheckMemoryState (0, 0, 1)

<br/>M ThRollIn: roll in T78/U26013/M0/I2 (level=7, abap_level=1, attach_em=1)

<br/>M ThCheckEmState: check ATTACH for em hdl 67

<br/>M ThCheckEmState: call EmContextAttach (em_hdl=67)

<br/>I Thu Dec 9 14:05:00 2010

<br/>I WARNING: MtxLock 0x70000000636197c rrol0046 owner=33 deadlock ?

<br/>I Thu Dec 9 14:06:00 2010

<br/>I WARNING: MtxLock 0x70000000636197c rrol0046 owner=33 deadlock ?

<br/>I Thu Dec 9 14:07:00 2010

<br/>I WARNING: MtxLock 0x70000000636197c rrol0046 owner=33 deadlock ?

<br/>I Thu Dec 9 14:08:00 2010

<br/>I WARNING: MtxLock 0x70000000636197c rrol0046 owner=33 deadlock ?

[Former Member]

hello,

any solution found ?

regards,

chaitanya

[markus_doehr2]

> <br/>We are now facing some problems on our smartform printing programs, sometimes some of the smartform programs look getting stuck, from SM50, the processing time is endless, and from the detailed tracing log, there are repeated messages like below for every ONE MINUTE:

> <br/>I WARNING: MtxLock 0x70000000636197c rrol0046 owner=33 deadlock ?

Check if the parameters from

Note 1309072 - System standstill: MtxLock EMADM

help

Markus

[Former Member]

I've provided all the information that I collected to the Basis guy but seems he is not worry about this issue. So I don't know whether the information is enough to solve our problem. So let's close this topic and I will post solution later if found.

Thank you very much for the help.

Best Regards,

Jeff

[Former Member]

Hi,

Ecxept deadlock situation there was no other error/warning messages observed.

Are smartforms custom built?

One chance of deadlock was if there is parllel processing on table level then deadlock situations occur frequently, check if parllel processing was active on the affecting tables.

Better get SAP involved.

Regards,

Sitarama.

[Former Member]

Hi Sitarama,

<br/>

<br/>Thanks very much for your fast reply. Yes, the smartforms are custom-built. Besides the deadlock error, there still has some errors in SP01 says "Could not pass request to host spool system". But it previews wonderfully in SP01. The detailed SP01 error log is like below:

Print request processing log


Errors occurred processing this print request


Error during print request output. l_rc = 99
There may be no printout


Most important attributes of spool request

Request number 2828

Request name SMART  LOCA 8000199
Client 800
Owner 8000199
Request attributes
Time created   2010120906014800
Remaining life  +00007235800
Dispo 1 (Go/Hold) G
Dispo 2 (Keep/Delete)     D
Dispo 3 (Indirect/Direct) D
Default output device LOCA
Default no. copies  1
Format ZTEST
Main print request characteristics

Spool request number 2828
Print request number 1
Print request attributes
Time created   2010120906020500
Output device LOCA
Format ZTEST

What do you mean parallel processing on table level? The smartforms extract data from different SAP tables and then transfer to smartform interface, then they can added in form pages. Do you think this results parallel processing towards tables?

<br/>

Thank you and hope to hear more from you.

Best Regards,

Jeff