lunes, 29 de diciembre de 2014

Performance: configuración de bill items

En BRM podemos definir items custom (por ejemplo: /item/cargo_moratorio), dentro de éste tipo de item están los bill items.

No voy a entrar en detalle sobre como crear los bill items (ya esta explicado en la documentación online). Solamente voy a tocar el tema de la configuración de los mismos, específicamente la propiedad de precreate de los items.

La propiedad precreate especifica si BRM pre-creará o no el item para el tipo de servicio. En caso de que el valor sea true, el item se pre-creará en la base de datos (en la creación del servicio y en cada billing) y si el valor es false, el item se creará solamente cuando el evento ocurra.
Las tablas OOB mas grandes son la event_t (y las sub-tablas relacionadas a la clase /event) y la item_t. Entonces lo que menos queremos es que esas tablas crezcan innecesariamente.

Los procesos que deben ser lo mas eficientes (utilización de recursos y velocidad de procesamiento) posibles son el billing y el invoicing.

  1. Si configuramos los items como precreate="true" estaremos creando registros en la tabla item_t en la compra del servicio y en cada billing.
    1. En el caso de que para todas las cuentas siempre se generen eventos que caerán en el item definido como precreate el crecimiento de la tabla item_t no será innecesario (ya que si o si se crearán esos items) pero si estaremos degradando la performance del billing ya que durante el billing se crearán los items para el nuevo bill.
    2. En el caso de que para todas las cuentas NO siempre se generen eventos que caerán en el item definido como precreate el crecimiento de la tabla item_t será innecesario (ya que estaremos creando registros que no tendran eventos asociados ni impactos de ningún tipo, tanto como monetarios como no monetadios) y estaremos degradando la performance del billing ya que durante el billing se crearán los items para el nuevo bill y tambien decaerá la performace del invoicing ya que se procesaran tambien los items vacios(sin eventos).
  2. Si configuramos los items como precreate="false" estaremos creando registros en la tabla item_t solamente cuanto ocurra el evento asociado a nuestro bill item.
    1. En el caso de que para todas las cuentas siempre se generen eventos que caerán en el item definido como no precreate el crecimiento de la tabla item_t no será innecesario (ya que si o si se crearán esos items), la performance del billing será similar con o sin el precreate (ya que si el precreate es false no se crearan los items para el próximo bill, pero si se crearán los items para el bill actual).
    2. En el caso de que para todas las cuentas NO siempre se generen eventos que caerán en el item definido como no precreate el crecimiento de la tabla item_t no será innecesario (ya que solamente se crearán los items cuando ocurran los eventos) y no estaremos degradando la performance del billing ni la de invoicing.

Ahora hagamos algunas pruebas (con precreate="true") para corroborar la teoría expresada arriba.

Primero vamos a configurar nuestro ambiente para que el log del dm_oracle nos muestre todas las queries ejecutadas. Luego le ejecutamos billing a un billinfo para ver que queries se ejecutan (solamente tomaré en cuenta las queries de los items que no tienen eventos asociados, items creados innecesariamente).

  1. Queries ejecutadas durante el billing: 6 inserts (uno por cada item que se está pre-creando)
    1. dm_oracle.log:
      DDD get_new_poid_id: Going to the Sequence Cache to retrieve new poid id.
      DDD get_poid_id_from_cache: got 2640875 for /item/bundle
      SQL_STMT do_sql_insert: cmd=insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
      DDD get_new_poid_id: Going to the Sequence Cache to retrieve new poid id.
      DDD get_poid_id_from_cache: got 2639851 for /item/video
      SQL_STMT do_sql_insert: cmd=insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
      DDD get_new_poid_id: Going to the Sequence Cache to retrieve new poid id.
      DDD get_poid_id_from_cache: got 2641899 for /item/promotion
      SQL_STMT do_sql_insert: cmd=insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
      DDD get_new_poid_id: Going to the Sequence Cache to retrieve new poid id.
      DDD get_poid_id_from_cache: got 2637851 for /item/telephony
      SQL_STMT do_sql_insert: cmd=insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
      DDD get_new_poid_id: Going to the Sequence Cache to retrieve new poid id.
      DDD get_poid_id_from_cache: got 2639899 for /item/bundle
      SQL_STMT do_sql_insert: cmd=insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
      DDD get_new_poid_id: Going to the Sequence Cache to retrieve new poid id.
      DDD get_poid_id_from_cache: got 2638875 for /item/promotion
      SQL_STMT do_sql_insert: cmd=insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
      
      
    2. dm_oracle.pinlog: (solo mostraré el resumen de un insert y el tiempo tomado por los otros 5 insert)
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):7319 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       Start of opcode PCM_OP_CREATE_OBJ
      W Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_subr.c(162):2809 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       
      SQL_STMT do_sql_insert: cmd="insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )"
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  ../dm_oracle_stmt_cache.c:366 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       PINStmtPrepare: SQL Statement = insert into item_t ( poid_DB, poid_ID0, poid_TYPE, poid_REV, name, status, closed_t, effective_t, opened_t, due_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, gl_segment, currency, disputed, recvd, adjusted, transfered, writeoff, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, bal_grp_obj_DB, bal_grp_obj_ID0, bal_grp_obj_TYPE, bal_grp_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, created_t, mod_t, read_access, write_access, archive_status, ar_bill_obj_DB, ar_bill_obj_ID0, ar_bill_obj_TYPE, ar_bill_obj_REV, currency_operator, currency_rate, currency_secondary, delta_due, due, event_poid_list, flags, item_no, item_total ) values ( :poid_DB, :poid_ID0, :poid_TYPE, :poid_REV, :name, :status, :closed_t, :effective_t, :opened_t, :due_t, :account_obj_DB, :account_obj_ID0, :account_obj_TYPE, :account_obj_REV, :bill_obj_DB, :bill_obj_ID0, :bill_obj_TYPE, :bill_obj_REV, :gl_segment, :currency, :disputed, :recvd, :adjusted, :transfered, :writeoff, :service_obj_DB, :service_obj_ID0, :service_obj_TYPE, :service_obj_REV, :bal_grp_obj_DB, :bal_grp_obj_ID0, :bal_grp_obj_TYPE, :bal_grp_obj_REV, :billinfo_obj_DB, :billinfo_obj_ID0, :billinfo_obj_TYPE, :billinfo_obj_REV, :ar_billinfo_obj_DB, :ar_billinfo_obj_ID0, :ar_billinfo_obj_TYPE, :ar_billinfo_obj_REV, :created_t, :mod_t, :read_access, :write_access, :archive_status, :ar_bill_obj_DB, :ar_bill_obj_ID0, :ar_bill_obj_TYPE, :ar_bill_obj_REV, :currency_operator, :currency_rate, :currency_secondary, :delta_due, :due, :event_poid_list, :flags, :item_no, :item_total )
       audsession-id: 13393425; Statement-id: 4208176;
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  ../dm_oracle_stmt_cache.c:376 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Statement-id: 4208176; Time taken by OCIStmtPrepare = 0.370026 milliseconds
      ...
      ...
      ...
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):932 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Statement-id: 4208176; Time taken by ExecuteSQLStmt = 9.946108 milliseconds
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9613 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       End of opcode PCM_OP_CREATE_OBJ
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9615 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Time taken by PCM_OP_CREATE_OBJ = 12.897968 milliseconds
      
      
      (los 5 insert que faltan)
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9615 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Time taken by PCM_OP_CREATE_OBJ = 2.813101 milliseconds
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9615 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Time taken by PCM_OP_CREATE_OBJ = 2.745867 milliseconds
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9615 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Time taken by PCM_OP_CREATE_OBJ = 2.729177 milliseconds
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9615 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Time taken by PCM_OP_CREATE_OBJ = 2.936125 milliseconds
      D Sun Jan 11 00:03:50 2015  brmtin  dm:20534  dm_if_oracle.c(206):9615 1:brmtin:pin_bill_accts:20621:5:0:1416326321:0
       audsession-id: 13393425; Time taken by PCM_OP_CREATE_OBJ = 2.928972 milliseconds 
       
      En total los 6 inserts consumieron 27.05121 milisegundos
  2. Queries ejecutadas durante invoicing: 
    1.  dm_oracle.log:
      SQL_STMT do_sql_mr_select: cmd=select   service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, item_no, name, item_total, due_t, due, disputed, event_poid_list, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, effective_t, created_t, poid_DB, poid_ID0, poid_TYPE, poid_REV from item_t   where ( item_t.ar_bill_obj_ID0 = :1  or ( item_t.effective_t >= :2 and item_t.effective_t < :3 and item_t.ar_billinfo_obj_ID0 = :4  and item_t.bill_obj_ID0 = :5  )  )
      SQL_STMT do_sql_mr_select: cmd=select  distinct  event_t.poid_DB, event_t.poid_ID0, event_t.poid_TYPE, event_t.poid_REV, event_t.end_t, event_t.start_t, event_t.created_t, event_t.net_quantity, event_t.sys_descr, event_t.rerate_obj_DB, event_t.rerate_obj_ID0, event_t.rerate_obj_TYPE, event_t.rerate_obj_REV, event_t.session_obj_DB, event_t.session_obj_ID0, event_t.session_obj_TYPE, event_t.session_obj_REV, event_t.invoice_data, event_t.timezone_adj_end_t, event_t.rated_timezone_id, event_t.item_obj_DB, event_t.item_obj_ID0, event_t.item_obj_TYPE, event_t.item_obj_REV from event_t ,item_t   where item_t.poid_ID0 = event_t.item_obj_ID0 and (( item_t.ar_bill_obj_ID0 = :1  ) or  ( item_t.ar_billinfo_obj_ID0 = :2    and  item_t.effective_t >= :3 and  item_t.effective_t < :4 ))  and event_t.created_t >= :5 and event_t.created_t <= :6 and event_t.poid_type in( select type_str from config_invoice_event_types_t where obj_id0 = 102 ) and event_t.poid_type not like '%/event/delayed/session/telco%' and ((event_t.poid_ID0 >= :7 and event_t.poid_ID0 < :8) or (event_t.poid_ID0 >= :9 and event_t.poid_ID0 <= :10) or (event_t.poid_ID0 >= :11 and event_t.poid_ID0 <= :12)) 
      SQL_STMT do_sql_mr_select: cmd=select  distinct  event_t.poid_DB, event_t.poid_ID0, event_t.poid_TYPE, event_t.poid_REV, event_t.end_t, event_t.start_t, event_t.created_t, event_t.net_quantity, event_t.sys_descr, event_t.rerate_obj_DB, event_t.rerate_obj_ID0, event_t.rerate_obj_TYPE, event_t.rerate_obj_REV, event_t.session_obj_DB, event_t.session_obj_ID0, event_t.session_obj_TYPE, event_t.session_obj_REV, event_t.invoice_data, event_t.timezone_adj_end_t, event_t.rated_timezone_id, event_t.item_obj_DB, event_t.item_obj_ID0, event_t.item_obj_TYPE, event_t.item_obj_REV from event_t ,item_t   where item_t.poid_ID0 = event_t.item_obj_ID0 and (( item_t.ar_bill_obj_ID0 = :1  ) or  ( item_t.ar_billinfo_obj_ID0 = :2    and  item_t.effective_t >= :3 and  item_t.effective_t < :4 ))  and event_t.created_t >= :5 and event_t.created_t <= :6 and event_t.poid_type in( select type_str from config_invoice_event_types_t where obj_id0 = 102 ) and event_t.poid_type like '%/event/delayed/session/telco%' and ((event_t.poid_ID0 >= :7 and event_t.poid_ID0 < :8) or (event_t.poid_ID0 >= :9 and event_t.poid_ID0 <= :10) or (event_t.poid_ID0 >= :11 and event_t.poid_ID0 <= :12)) 
      
    2.  dm_oracle.pinlog:
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):7319 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       Start of opcode PCM_OP_STEP_SEARCH
      W Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_search.c(110):1418 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       
      SQL_STMT dm_search_robj: cmd="select   service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV, item_no, name, item_total, due_t, due, disputed, event_poid_list, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, effective_t, created_t, poid_DB, poid_ID0, poid_TYPE, poid_REV from item_t   where ( item_t.ar_bill_obj_ID0 = :1  or ( item_t.effective_t >= :2 and item_t.effective_t < :3 and item_t.ar_billinfo_obj_ID0 = :4  and item_t.bill_obj_ID0 = :5  )  )"
      ...
      ...
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9615 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       audsession-id: 13431992; Time taken by PCM_OP_STEP_SEARCH = 4.986048 milliseconds
      ...
      ... 
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):7319 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       Start of opcode PCM_OP_STEP_SEARCH
      W Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_search.c(110):1418 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       
      SQL_STMT dm_search_robj: cmd="select  distinct  event_t.poid_DB, event_t.poid_ID0, event_t.poid_TYPE, event_t.poid_REV, event_t.end_t, event_t.start_t, event_t.created_t, event_t.net_quantity, event_t.sys_descr, event_t.rerate_obj_DB, event_t.rerate_obj_ID0, event_t.rerate_obj_TYPE, event_t.rerate_obj_REV, event_t.session_obj_DB, event_t.session_obj_ID0, event_t.session_obj_TYPE, event_t.session_obj_REV, event_t.invoice_data, event_t.timezone_adj_end_t, event_t.rated_timezone_id, event_t.item_obj_DB, event_t.item_obj_ID0, event_t.item_obj_TYPE, event_t.item_obj_REV from event_t ,item_t   where item_t.poid_ID0 = event_t.item_obj_ID0 and (( item_t.ar_bill_obj_ID0 = :1  ) or  ( item_t.ar_billinfo_obj_ID0 = :2    and  item_t.effective_t >= :3 and  item_t.effective_t < :4 ))  and event_t.created_t >= :5 and event_t.created_t <= :6 and event_t.poid_type in( select type_str from config_invoice_event_types_t where obj_id0 = 102 ) and event_t.poid_type not like '%/event/delayed/session/telco%' and ((event_t.poid_ID0 >= :7 and event_t.poid_ID0 < :8) or (event_t.poid_ID0 >= :9 and event_t.poid_ID0 <= :10) or (event_t.poid_ID0 >= :11 and event_t.poid_ID0 <= :12)) "
      ...
      ... 
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9613 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       End of opcode PCM_OP_STEP_SEARCH
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9615 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       audsession-id: 13431992; Time taken by PCM_OP_STEP_SEARCH = 7.750988 milliseconds
      ...
      ...  
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):7319 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       Start of opcode PCM_OP_STEP_SEARCH
      W Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_search.c(110):1418 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       
      SQL_STMT dm_search_robj: cmd="select  distinct  event_t.poid_DB, event_t.poid_ID0, event_t.poid_TYPE, event_t.poid_REV, event_t.end_t, event_t.start_t, event_t.created_t, event_t.net_quantity, event_t.sys_descr, event_t.rerate_obj_DB, event_t.rerate_obj_ID0, event_t.rerate_obj_TYPE, event_t.rerate_obj_REV, event_t.session_obj_DB, event_t.session_obj_ID0, event_t.session_obj_TYPE, event_t.session_obj_REV, event_t.invoice_data, event_t.timezone_adj_end_t, event_t.rated_timezone_id, event_t.item_obj_DB, event_t.item_obj_ID0, event_t.item_obj_TYPE, event_t.item_obj_REV from event_t ,item_t   where item_t.poid_ID0 = event_t.item_obj_ID0 and (( item_t.ar_bill_obj_ID0 = :1  ) or  ( item_t.ar_billinfo_obj_ID0 = :2    and  item_t.effective_t >= :3 and  item_t.effective_t < :4 ))  and event_t.created_t >= :5 and event_t.created_t <= :6 and event_t.poid_type in( select type_str from config_invoice_event_types_t where obj_id0 = 102 ) and event_t.poid_type like '%/event/delayed/session/telco%' and ((event_t.poid_ID0 >= :7 and event_t.poid_ID0 < :8) or (event_t.poid_ID0 >= :9 and event_t.poid_ID0 <= :10) or (event_t.poid_ID0 >= :11 and event_t.poid_ID0 <= :12)) "
      ...
      ...
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9613 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       End of opcode PCM_OP_STEP_SEARCH
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9615 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       audsession-id: 13431992; Time taken by PCM_OP_STEP_SEARCH = 5.136013 milliseconds
      ...
      ... 
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):7319 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       Start of opcode PCM_OP_SEARCH
      W Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_search.c(110):1418 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       
      SQL_STMT dm_search_robj: cmd="select  distinct  poid_DB, poid_ID0, poid_TYPE, poid_REV, item_no, name, item_total, due, transfered, effective_t, created_t, account_obj_DB, account_obj_ID0, account_obj_TYPE, account_obj_REV, billinfo_obj_DB, billinfo_obj_ID0, billinfo_obj_TYPE, billinfo_obj_REV, ar_billinfo_obj_DB, ar_billinfo_obj_ID0, ar_billinfo_obj_TYPE, ar_billinfo_obj_REV, event_poid_list, bill_obj_DB, bill_obj_ID0, bill_obj_TYPE, bill_obj_REV, disputed, due_t, service_obj_DB, service_obj_ID0, service_obj_TYPE, service_obj_REV from item_t   where item_t.billinfo_obj_ID0 = :1 and item_t.created_t >= :2 and item_t.created_t < :3  and item_t.poid_type in ('/item/payment','/item/payment/reversal')  and ((item_t.poid_ID0 >= :4 and item_t.poid_ID0 <= :5)) "
      ...
      ...
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9613 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       End of opcode PCM_OP_SEARCH
      D Wed Jan 11 23:52:41 2015  brmtin  dm:3011  dm_if_oracle.c(206):9615 1:brmtin:pin_inv_accts:3158:2:953:1416425033:1
       audsession-id: 13431992; Time taken by PCM_OP_SEARCH = 4.098892 milliseconds
      
Al ejecutar el billing, como se oberva en el log, el tiempo para crear los 6 items fue de 27 milisegundos (para la creación del primer item se tomó demasiado tiempo, la voy a tomar como un promedio de las otras 5, lo que me da 2.8306484 milisegundos, entonces quedaría un total de 16.9838904 milisegundos). Quizas 17 milisegundos no sea mucho tiempo, pero por cada millón de bills que se generen serían 17 millones de milisegundos (4.72 horas), que si los dividimos en 64 threads da un total de 4.42 minutos más de tiempo de procesamiento por thread. No es mucho tiempo. El mayor impacto se da en la creación innecesaria de items vacíos (sin eventos) en la base de datos.

Realicemos un ejercicio:
Supongamos que de los 6 items precreados, siempre se usarán 4 en cada billing, lo que nos deja 2 items creados innecesariamente (por ejemplo los utilizados para los cargos únicos o promociones que los clientes tienen 1 o 2 veces al año, el resto de las veces serán items vacios), y que por cada mes se generan 1 millón de bills, lo que deja 2 millones de registros innecesarios en la base de datos. Tiene sentido meterle anualmente 24 millones de registros innecesarios a una tabla? Definitivamente no.

La recomendación es que cuando se configuren los bill items, en el 99% de los casos(solamente en ocasiones muy especiales es necesario que el precreate sea true) éstos tengan la propiedad precreate="false".

Martín Falconi

2 comentarios:

  1. muy buen articulo, que piensas de que los items sean type="cumulative" o type="individual".

    ResponderBorrar
    Respuestas
    1. Gracias Mauricio. El tema de cumulative o individual, dependerá de los usos que les demos a dichos items y si queremos agrupar los eventos en items o no.

      Por ejemplo: para llamadas telefónicas, en dicho caso deberían ser cumulative ya que un item podría contener miles de eventos (llamadas) y si fuera individual se estaría creando un item por cada evento(llamada).
      Otro ejemplo de usar cumulative para que en el mismo caso nos queden asociados los eventos de un mismo producto, si en un mismo ciclo un producto es inactivado (generando prorrateo), luego reactivado(generando otro prorrateo durante el billing) ahi en el mismo item tenemos los 2 eventos generados y es mas facil para agrupar en el invoicing el saldo de dicho producto ya que todo queda dentro del mismo item.

      Borrar