Hitachi Vantara Pentaho Community Forums
Results 1 to 4 of 4

Thread: slow execution and strange behaviour of report with data source Olap Pentaho Analysis

  1. #1

    Default slow execution and strange behaviour of report with data source Olap Pentaho Analysis

    I have implemented a report that use a datasource of type Olap Pentaho Analysis .
    The execution time of the query ( see the log that follow ) is about 7 seconds ( mdx and sql mondrian log enabled ) .
    But the exetution time of the report is much more ( i have activated the PerformanceProgressLogger , see the log that follow) :

    1° phase : 40461ms
    2° phase : 21845ms

    I have activated all the possible log but i can't undestand what the reporting engine is doing .
    The report result is of only tre page ( the main query is a rank of 0 records over about 8800 record of a dimension ) .

    thanks for any answer .

    follow the log :

    2014-10-28 16:26:15,231 ERROR [org.pentaho.platform.web.servlet.GenericServlet] GenericServlet.ERROR_0004 - Resource /saiku-ui/saikuplugin.properties_supported_languages.properties not found in plugin saiku
    2014-10-28 16:26:15,242 ERROR [org.pentaho.platform.web.servlet.GenericServlet] GenericServlet.ERROR_0004 - Resource /saiku-ui/saikuplugin.properties.properties not found in plugin saiku
    2014-10-28 16:26:15,251 ERROR [org.pentaho.platform.web.servlet.GenericServlet] GenericServlet.ERROR_0004 - Resource /saiku-ui/saikuplugin.properties_it.properties not found in plugin saiku
    2014-10-28 16:26:15,264 ERROR [org.pentaho.platform.web.servlet.GenericServlet] GenericServlet.ERROR_0004 - Resource /saiku-ui/saikuplugin.properties_it_IT.properties not found in plugin saiku
    2014-10-28 16:27:10,332 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-6] Report Processing started. Free: 682757432; Total: 1038876672
    2014-10-28 16:27:25,826 DEBUG [mondrian.mdx] 182: with member [Measures].[Descrizione cliente fatturazione] as '[CLIENTIF.Clienti Fatturazione].[Clienti Fatturazione].CurrentMember.Properties("Descrizione")'
    select NON EMPTY {[Measures].[Descrizione cliente fatturazione], [Measures].[ValoreRoundedCY], [Measures].[RankValoreCYF], [Measures].[ValoreRoundedPY], [Measures].[RankValorePYF], [Measures].[ValoreRoundedPPY], [Measures].[RankValorePPYF]} ON COLUMNS,
    NON EMPTY Subset(Order({Hierarchize({[CLIENTIF.Clienti Fatturazione].[Clienti Fatturazione].Members})}, [Measures].[ValoreRoundedPY], BDESC), 0, 50) ON ROWS
    from [Fatturato]


    2014-10-28 16:27:25,857 DEBUG [mondrian.sql] 0: SqlTupleReader.readTuples [[CLIENTIF.Clienti Fatturazione].[Clienti Fatturazione]]: executing sql [select "CUSTOMER"."ID" as "c0", "CUSTOMER"."DESCRIPTION" as "c1", "CUSTOMER"."DESCRIPTION" as "c2" from "OLAPANTO"."CUSTOMER" "CUSTOMER" group by "CUSTOMER"."ID", "CUSTOMER"."DESCRIPTION" order by "CUSTOMER"."ID" ASC NULLS LAST]
    2014-10-28 16:27:25,922 DEBUG [mondrian.sql] 0: , exec 61 ms
    2014-10-28 16:27:26,731 DEBUG [mondrian.sql] 0: , exec+fetch 873 ms, 8808 rows
    2014-10-28 16:27:26,925 DEBUG [mondrian.sql] 1: SqlTupleReader.readTuples [[DATA.Data Fattura].[Anno]]: executing sql [select "TIME_BY_DAY"."THE_YEAR" as "c0", "TIME_BY_DAY"."THE_YEAR" as "c1" from "OLAPANTO"."TIME_BY_DAY" "TIME_BY_DAY" group by "TIME_BY_DAY"."THE_YEAR" order by "TIME_BY_DAY"."THE_YEAR" ASC NULLS LAST]
    2014-10-28 16:27:26,929 DEBUG [mondrian.sql] 1: , exec 3 ms
    2014-10-28 16:27:26,930 DEBUG [mondrian.sql] 1: , exec+fetch 5 ms, 4 rows
    2014-10-28 16:27:27,641 DEBUG [mondrian.sql] 2: SqlStatisticsProvider.getColumnCardinality: executing sql [select count(distinct "THE_YEAR") from "OLAPANTO"."TIME_BY_DAY"]
    2014-10-28 16:27:27,643 DEBUG [mondrian.sql] 2: , exec 1 ms
    2014-10-28 16:27:27,643 DEBUG [mondrian.sql] 2: , exec+fetch 2 ms, 1 rows
    2014-10-28 16:27:27,644 DEBUG [mondrian.sql] 3: SqlStatisticsProvider.getColumnCardinality: executing sql [select count(distinct "ID") from "OLAPANTO"."CUSTOMER"]
    2014-10-28 16:27:27,656 DEBUG [mondrian.sql] 3: , exec 11 ms
    2014-10-28 16:27:27,656 DEBUG [mondrian.sql] 3: , exec+fetch 12 ms, 1 rows
    2014-10-28 16:27:27,945 DEBUG [mondrian.sql] 4: Segment.load: executing sql [select "TIME_BY_DAY"."THE_YEAR" as "c0", "CUSTOMER"."ID" as "c1", sum("INVOICE"."VALUE_INVOICE") as "m0" from "OLAPANTO"."TIME_BY_DAY" "TIME_BY_DAY", "OLAPANTO"."INVOICE" "INVOICE", "OLAPANTO"."CUSTOMER" "CUSTOMER" where "INVOICE"."TIME_ID" = "TIME_BY_DAY"."THE_DATE" and "TIME_BY_DAY"."THE_YEAR" = 2013 and "INVOICE"."CUSTOMERINVOICE_ID" = "CUSTOMER"."ID" group by "TIME_BY_DAY"."THE_YEAR", "CUSTOMER"."ID"]
    2014-10-28 16:27:28,153 DEBUG [mondrian.sql] 4: , exec 206 ms
    2014-10-28 16:27:28,666 DEBUG [mondrian.sql] 4: , exec+fetch 719 ms, 4894 rows
    2014-10-28 16:27:30,023 DEBUG [mondrian.sql] 5: Segment.load: executing sql [select "TIME_BY_DAY"."THE_YEAR" as "c0", "CUSTOMER"."ID" as "c1", sum("INVOICE"."VALUE_INVOICE") as "m0" from "OLAPANTO"."TIME_BY_DAY" "TIME_BY_DAY", "OLAPANTO"."INVOICE" "INVOICE", "OLAPANTO"."CUSTOMER" "CUSTOMER" where "INVOICE"."TIME_ID" = "TIME_BY_DAY"."THE_DATE" and "TIME_BY_DAY"."THE_YEAR" in (2012, 2014) and "INVOICE"."CUSTOMERINVOICE_ID" = "CUSTOMER"."ID" and "CUSTOMER"."ID" in ('A.F.M. SPA - 081960', 'ALLEANZA SALUTE DISTRIBUZIONE SPASED - 045187', 'AZIENDA SPECIALE "FARMACIE COMUNALI - 080497', 'BENNET SPA - 047558', 'CEF - COOP. ESERCENTI FARMACIA S.C.R - 042996', 'CF SPA - 047664', 'CO.RO.FAR. COOP. A R.L. SEDE $ - 081080', 'CO.TA.FAR.TI. SOC. COOP. - 160864', 'COFARDIS SPA - 092088', 'COMIFAR DISTRIBUZIONE SPA - 041537', 'CONFARMA DISTRIBUZIONE SPA - 047796', 'COOP ITALIA CONS.NAZ.NON ALIM. - 092250', 'CTF GROUP SOC COOPERATIVA SEDE - 040557', 'D.M. BARONE SPA - 191824', 'DIFARMA SPA SEDE - 200730', 'DIMAR SPA - 024742', 'ESSERE BENESSERE - 047425', 'EUROMED MEDICAL SERVICE SRL - 092041', 'F.CIE COMUNALI S.P.A. - 060352', 'FAP SRL - 020958', 'FARCOPA DISTRIBUZIONE SRL - 047648', 'FARLA SOCIETA'' COOPERATIVA - 140054', 'FARMACENTRO SERVIZI E LOGISTICA SOC. - 110874', 'FARMACENTRO SERVIZI LOGISTICA SOC. C - 100441', 'FARMACIE COMUNALI TORINO SPA - 024463', 'FARVIMA MEDICINALI S.P.A. SEDE - 150467', 'FINNERMAN GROUP SRL - 082875', 'G.S.M. GESTIONE SVILUPPO MARCHI SRL - 047439', 'GALENITALIA SPA - 140530', 'GUACCI S.P.A. - 150798', 'INNOVA PHARMA SPA - 047737', 'LA FARMACEUTICA SPA - 041499', 'MOLLICA ENRICO MEDICINALI SPA - 191823', 'NORD EST FARMA SPA SEDE - 055094', 'PL PHARMA SRL - 055585', 'QUALIFARMA RETAIL SRL SEDE - 082803', 'RAVENNA FARMACIE SRL - 081793', 'S.I.M.A. SPA - 200260', 'SAFAR SOCIETA'' COOPERATIVA SEDE - 120267', 'SINFARMA SOCIETA'' COOPERATIVA - 142887', 'SO.FARMA.MORRA SPA SEDE - 150702', 'SOFAD SRL - 191839', 'U.O. ECONOMICO FINANZIARIO AZIENDA - 082710', 'UFM SRL UNIONE FARMACEUTICA MILANESE - 047566', 'UNICO LA FARMACIA DEI FARMACISTI SPA - 046384', 'UNIFARM SARDEGNA SPA - 201028', 'UNIFARM SPA - 060134', 'UNIFARMA DISTRIBUZIONE SPA SEDE - 021185', 'UNIONE FARMACISTI LIGURI SPA - 031193', 'V.I.M. SRL SEDE - 170038') group by "TIME_BY_DAY"."THE_YEAR", "CUSTOMER"."ID"]
    2014-10-28 16:27:30,268 DEBUG [mondrian.sql] 5: , exec 245 ms
    2014-10-28 16:27:30,278 DEBUG [mondrian.sql] 5: , exec+fetch 255 ms, 96 rows
    2014-10-28 16:27:30,913 DEBUG [mondrian.mdx] 182: exec: 5087 ms
    2014-10-28 16:27:31,072 DEBUG [mondrian.mdx] 203: select NON EMPTY {[Measures].[ValoreRoundedPY], [Measures].[ValoreRoundedPPY], [Measures].[ValoreRoundedCY]} ON COLUMNS
    from [Fatturato]


    2014-10-28 16:27:32,033 DEBUG [mondrian.sql] 6: Segment.load: executing sql [select "TIME_BY_DAY"."THE_YEAR" as "c0", sum("INVOICE"."VALUE_INVOICE") as "m0" from "OLAPANTO"."TIME_BY_DAY" "TIME_BY_DAY", "OLAPANTO"."INVOICE" "INVOICE" where "INVOICE"."TIME_ID" = "TIME_BY_DAY"."THE_DATE" and "TIME_BY_DAY"."THE_YEAR" in (2012, 2014) group by "TIME_BY_DAY"."THE_YEAR"]
    2014-10-28 16:27:32,199 DEBUG [mondrian.sql] 6: , exec 165 ms
    2014-10-28 16:27:32,200 DEBUG [mondrian.sql] 6: , exec+fetch 167 ms, 2 rows
    2014-10-28 16:27:32,201 DEBUG [mondrian.mdx] 203: exec: 1129 ms
    2014-10-28 16:27:41,374 DEBUG [mondrian.mdx] 6095: select NON EMPTY {Hierarchize({[Measures].[Valore]})} ON COLUMNS,
    NON EMPTY Subset(Order({[DATA.Data Fattura].[Anno].Members}, [DATA.Data Fattura].[Anno].CurrentMember.Name, BDESC), 0, 1) ON ROWS
    from [Fatturato]


    2014-10-28 16:27:41,377 DEBUG [mondrian.mdx] 6095: exec: 2 ms
    2014-10-28 16:27:41,391 DEBUG [mondrian.mdx] 6114: select NON EMPTY {Hierarchize({[Measures].[Valore]})} ON COLUMNS,
    NON EMPTY Subset(Order({[DATA.Data Fattura].[Anno].Members}, [DATA.Data Fattura].[Anno].CurrentMember.Name, BDESC), 1, 1) ON ROWS
    from [Fatturato]


    2014-10-28 16:27:41,392 DEBUG [mondrian.mdx] 6114: exec: 1 ms
    2014-10-28 16:27:41,406 DEBUG [mondrian.mdx] 6133: select NON EMPTY {Hierarchize({[Measures].[Valore]})} ON COLUMNS,
    NON EMPTY Subset(Order({[DATA.Data Fattura].[Anno].Members}, [DATA.Data Fattura].[Anno].CurrentMember.Name, BDESC), 2, 1) ON ROWS
    from [Fatturato]


    2014-10-28 16:27:41,407 DEBUG [mondrian.mdx] 6133: exec: 1 ms
    2014-10-28 16:27:50,731 INFO [org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:27:50,731 INFO [org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-28 16:27:50,731 INFO [org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:27:50,731 INFO [org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:27:50,732 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:27:50,732 INFO [org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-28 16:27:50,732 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-28 16:27:50,732 INFO [org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker] Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=66, evaluated=2 (3,030303%), avoided=64 (96,969696%)
    2014-10-28 16:27:50,732 INFO [org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction] Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-28 16:27:50,794 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-6] Report Processing Finished: 40461ms - 1,236 rows/sec - Free: 720846216; Total: 1038876672
    2014-10-28 16:27:53,033 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-5] Report Processing started. Free: 807997504; Total: 1038876672
    2014-10-28 16:28:07,074 INFO [org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:07,075 INFO [org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-28 16:28:07,075 INFO [org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:07,075 INFO [org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:07,076 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:07,076 INFO [org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-28 16:28:07,076 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-28 16:28:07,077 INFO [org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker] Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=66, evaluated=2 (3,030303%), avoided=64 (96,969696%)
    2014-10-28 16:28:07,077 INFO [org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction] Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-28 16:28:14,822 INFO [org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:14,823 INFO [org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-28 16:28:14,823 INFO [org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:14,823 INFO [org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:14,823 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-28 16:28:14,823 INFO [org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-28 16:28:14,823 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-28 16:28:14,824 INFO [org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker] Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=133, evaluated=4 (3,007519%), avoided=129 (96,992477%)
    2014-10-28 16:28:14,824 INFO [org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction] Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-28 16:28:14,878 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-5] Report Processing Finished: 21845ms - 2,289 rows/sec - Free: 796691280; Total: 1038876672

  2. #2
    Join Date
    Mar 2003
    Posts
    8,085

    Default

    What version of the reporting engine are you using here?

    If you are using an 5.0 GA version of the reporting engine (or worse, a 4.8 version) to do Crosstabs then you will feel pain. So do you use a 5.1 or even a 5.2 GA version?
    Get the latest news and tips and tricks for Pentaho Reporting at the Pentaho Reporting Blog.

  3. #3

    Default

    i'm using pentaho BA 5.1 ( the log is about a report executing on the server ) .
    i don't use crosstab ( the query is not denormalized ) and i don't want crosstab ; i get the mdx output as is .

    i have activated other performance indicator and now i have a log much more clear ( see below ) .
    i think it is clear that the bottleneck is not the mdx query .
    the number of record is very limited ( 50 records in 3 pages ) and there in no subreports .
    the only thing that can confuse the report engine is 3 static total ( calculated in the page header ) not at the end of the report .
    but the strangest thing is that the same report executed from the report designer is very fast .
    i don't know what are the activity at level 2 and 3 but they seems to me too slow .
    probably there is something on the report that undermine the report engine .
    thanks for any help

    2014-10-29 09:27:32,277 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Report Processing started. Free: 634941480; Total: 10388766722014-10-29 09:27:32,310 DEBUG [mondrian.mdx] 34713: with member [Measures].[Descrizione cliente fatturazione] as '[CLIENTIF.Clienti Fatturazione].[Clienti Fatturazione].CurrentMember.Properties("Descrizione")'
    select NON EMPTY {[Measures].[Descrizione cliente fatturazione], [Measures].[ValoreRoundedCY], [Measures].[RankValoreCYF], [Measures].[ValoreRoundedPY], [Measures].[RankValorePYF], [Measures].[ValoreRoundedPPY], [Measures].[RankValorePPYF]} ON COLUMNS,
    NON EMPTY Subset(Order({Hierarchize({[CLIENTIF.Clienti Fatturazione].[Clienti Fatturazione].Members})}, [Measures].[ValoreRoundedPY], BDESC), 0, 50) ON ROWS
    from [Fatturato]


    2014-10-29 09:27:33,190 DEBUG [mondrian.mdx] 34713: exec: 879 ms
    2014-10-29 09:27:33,312 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 1 Level: 0 Processing page: 0 Row: 0 Time: 1035ms Free: 730648040; Total: 1038876672
    2014-10-29 09:27:33,324 DEBUG [mondrian.mdx] 34732: select NON EMPTY {[Measures].[ValoreRoundedPY], [Measures].[ValoreRoundedPPY], [Measures].[ValoreRoundedCY]} ON COLUMNS
    from [Fatturato]


    2014-10-29 09:27:33,327 DEBUG [mondrian.mdx] 34732: exec: 3 ms
    2014-10-29 09:27:38,661 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 2 Level: 1 Processing page: 1 Row: 0 Time: 6384ms Free: 622116704; Total: 1038876672
    2014-10-29 09:27:38,717 DEBUG [mondrian.mdx] 40624: select NON EMPTY {Hierarchize({[Measures].[Valore]})} ON COLUMNS,
    NON EMPTY Subset(Order({[DATA.Data Fattura].[Anno].Members}, [DATA.Data Fattura].[Anno].CurrentMember.Name, BDESC), 0, 1) ON ROWS
    from [Fatturato]


    2014-10-29 09:27:38,719 DEBUG [mondrian.mdx] 40624: exec: 1 ms
    2014-10-29 09:27:38,729 DEBUG [mondrian.mdx] 40643: select NON EMPTY {Hierarchize({[Measures].[Valore]})} ON COLUMNS,
    NON EMPTY Subset(Order({[DATA.Data Fattura].[Anno].Members}, [DATA.Data Fattura].[Anno].CurrentMember.Name, BDESC), 1, 1) ON ROWS
    from [Fatturato]


    2014-10-29 09:27:38,730 DEBUG [mondrian.mdx] 40643: exec: 0 ms
    2014-10-29 09:27:38,740 DEBUG [mondrian.mdx] 40662: select NON EMPTY {Hierarchize({[Measures].[Valore]})} ON COLUMNS,
    NON EMPTY Subset(Order({[DATA.Data Fattura].[Anno].Members}, [DATA.Data Fattura].[Anno].CurrentMember.Name, BDESC), 2, 1) ON ROWS
    from [Fatturato]


    2014-10-29 09:27:38,741 DEBUG [mondrian.mdx] 40662: exec: 0 ms
    2014-10-29 09:27:42,258 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 2 Level: 1 Processing page: 2 Row: 0 Time: 9981ms Free: 674756448; Total: 1038876672
    2014-10-29 09:27:45,301 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 2 Level: 1 Processing page: 3 Row: 0 Time: 13024ms Free: 825109600; Total: 1038876672
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 09:27:45,801 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-29 09:27:45,802 INFO [org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker] Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=66, evaluated=2 (3,030303%), avoided=64 (96,969696%)
    2014-10-29 09:27:45,802 INFO [org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction] Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-29 09:27:45,851 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 3 Level: 1 Processing page: 1 Row: 0 Time: 13574ms Free: 696176776; Total: 1038876672
    2014-10-29 09:27:49,372 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 3 Level: 1 Processing page: 2 Row: 0 Time: 17095ms Free: 757831280; Total: 1038876672
    2014-10-29 09:27:52,331 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Activity: 3 Level: 1 Processing page: 3 Row: 0 Time: 20054ms Free: 622787440; Total: 1038876672
    2014-10-29 09:27:52,860 INFO [org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:52,861 INFO [org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 09:27:52,861 INFO [org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:52,861 INFO [org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:52,861 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 09:27:52,861 INFO [org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 09:27:52,861 INFO [org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator] Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-29 09:27:52,862 INFO [org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker] Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=133, evaluated=4 (3,007519%), avoided=129 (96,992477%)
    2014-10-29 09:27:52,862 INFO [org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction] Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-29 09:27:52,935 INFO [org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger] [http-8080-2] Report Processing Finished: 20658ms - 2,420 rows/sec - Free: 775087680; Total: 1038876672

  4. #4

    Default

    i have attached also the log of the same report executed on the pentaho report designer .
    the performnce indicators are very different and the report is executed on a host much less powerfull of that where pentaho BA is intalled

    2014-10-29 10:14:49,809 [ 81291] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Report Processing started. Free: 37895816; Total: 183762944
    2014-10-29 10:14:49,869 [ 81351] DEBUG - org.pentaho.reporting.engine.classic.extensions.datasources.mondrian.DefaultMondrianConnectionProvider - Creating Mondrian connection: provider=mondrian; Catalog=C:\sviluppo\marcoa\olapanto.xml; Locale=it_IT
    2014-10-29 10:14:49,879 [ 81361] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: Starting
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Tablemodel contains 50 rows.
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 0 Name = [CLIENTIF.Clienti Fatturazione].[(All)]; DataType = class java.lang.String
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 1 Name = [CLIENTIF.Clienti Fatturazione].[Clienti Fatturazione]; DataType = class java.lang.String
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 2 Name = [Measures].[Descrizione cliente fatturazione]; DataType = class java.lang.String
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 3 Name = [Measures].[ValoreRoundedCY]; DataType = class java.lang.Double
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 4 Name = [Measures].[RankValoreCYF]; DataType = class java.lang.Integer
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 5 Name = [Measures].[ValoreRoundedPY]; DataType = class java.lang.Double
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 6 Name = [Measures].[RankValorePYF]; DataType = class java.lang.Integer
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 7 Name = [Measures].[ValoreRoundedPPY]; DataType = class java.lang.Double
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 8 Name = [Measures].[RankValorePPYF]; DataType = class java.lang.Integer
    2014-10-29 10:14:51,602 [ 83084] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Checking the data inside
    2014-10-29 10:14:51,702 [ 83184] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: 1.823
    2014-10-29 10:14:51,742 [ 83224] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 1 Level: 0 Processing page: 0 Row: 0 Time: 1933ms Free: 67829832; Total: 183762944
    2014-10-29 10:14:51,752 [ 83234] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: Starting
    2014-10-29 10:14:53,985 [ 85467] DEBUG - org.pentaho.platform.engine.core.system.InheritableThreadLocalPentahoSessionHolderStrategy - No session bound to this thread mondrian.rolap.agg.SegmentCacheManager$sqlExecutor_3
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Tablemodel contains 1 rows.
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 0 Name = [Measures].[ValoreRoundedPY]; DataType = class java.lang.Double
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 1 Name = [Measures].[ValoreRoundedPPY]; DataType = class java.lang.Double
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 2 Name = [Measures].[ValoreRoundedCY]; DataType = class java.lang.Double
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Checking the data inside
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 0) is 9735143.0
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 1) is 9303323.0
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 2) is 7184887.0
    2014-10-29 10:14:54,236 [ 85718] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: 2.484
    2014-10-29 10:14:55,267 [ 86749] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 2 Level: 1 Processing page: 1 Row: 0 Time: 5458ms Free: 58734536; Total: 183762944
    2014-10-29 10:14:55,277 [ 86759] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: Starting
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Tablemodel contains 1 rows.
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 0 Name = [DATA.Data Fattura].[(All)]; DataType = class java.lang.String
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 1 Name = [DATA.Data Fattura].[Anno]; DataType = class java.lang.String
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 2 Name = [Measures].[Valore]; DataType = class java.lang.Double
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Checking the data inside
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 0) is Tutte le Date Fattura
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 1) is 2014
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 2) is 7184887.36
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: 0.0
    2014-10-29 10:14:55,287 [ 86769] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: Starting
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Tablemodel contains 1 rows.
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 0 Name = [DATA.Data Fattura].[(All)]; DataType = class java.lang.String
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 1 Name = [DATA.Data Fattura].[Anno]; DataType = class java.lang.String
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 2 Name = [Measures].[Valore]; DataType = class java.lang.Double
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Checking the data inside
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 0) is Tutte le Date Fattura
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 1) is 2013
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 2) is 9735143.419999983
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: 0.01
    2014-10-29 10:14:55,297 [ 86779] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: Starting
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Tablemodel contains 1 rows.
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 0 Name = [DATA.Data Fattura].[(All)]; DataType = class java.lang.String
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 1 Name = [DATA.Data Fattura].[Anno]; DataType = class java.lang.String
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Column: 2 Name = [Measures].[Valore]; DataType = class java.lang.Double
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - Checking the data inside
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 0) is Tutte le Date Fattura
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 1) is 2012
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - ValueAt (0, 2) is 9303322.91
    2014-10-29 10:14:55,307 [ 86789] DEBUG - org.pentaho.reporting.engine.classic.core.cache.CachingDataFactory - 30772495: Query processing time: 0.01
    2014-10-29 10:14:56,205 [ 87687] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 2 Level: 1 Processing page: 2 Row: 0 Time: 6396ms Free: 19682672; Total: 183762944
    2014-10-29 10:14:56,736 [ 88218] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 2 Level: 1 Processing page: 3 Row: 0 Time: 6927ms Free: 56888112; Total: 183762944
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker - Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=66, evaluated=2 (3,030303%), avoided=64 (96,969696%)
    2014-10-29 10:14:56,866 [ 88348] INFO - org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction - Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-29 10:14:56,896 [ 88378] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 3 Level: 1 Processing page: 1 Row: 0 Time: 7087ms Free: 43944024; Total: 183762944
    2014-10-29 10:14:57,547 [ 89029] DEBUG - org.pentaho.reporting.engine.classic.core.modules.output.pageable.pdf.internal.PdfDocumentWriter - viewerPreferences = 0b100000000000000001
    2014-10-29 10:14:57,657 [ 89139] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 3 Level: 1 Processing page: 2 Row: 0 Time: 7848ms Free: 15449808; Total: 183762944
    2014-10-29 10:14:58,118 [ 89600] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Activity: 3 Level: 1 Processing page: 3 Row: 0 Time: 8309ms Free: 50274544; Total: 183762944
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.AttributeExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.SheetNameFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.MetaDataStyleEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.WizardItemHideFunction => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleExpressionsEvaluator => total=282, evaluated=14 (4,964539%), avoided=268 (95,035461%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.CellFormatFunction => total=0, evaluated=0 (0,000000%), avoided=0 (0,000000%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator - Performance: class org.pentaho.reporting.engine.classic.core.function.sys.StyleResolvingEvaluator => total=282, evaluated=21 (7,446808%), avoided=261 (92,553192%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker - Performance: class org.pentaho.reporting.engine.classic.core.layout.output.ElementChangeChecker => total=133, evaluated=4 (3,007519%), avoided=129 (96,992477%)
    2014-10-29 10:14:58,188 [ 89670] INFO - org.pentaho.reporting.engine.classic.core.layout.output.DefaultOutputFunction - Performance: footer-printed=6 footer-avoided=53 repeating-footer-printed=4 repeating-footer-avoided=55
    2014-10-29 10:14:58,218 [ 89700] DEBUG - org.pentaho.reporting.libraries.fonts.itext.ITextFontStorage - Font-Storage: hits=0, misses=5
    2014-10-29 10:14:58,218 [ 89700] INFO - org.pentaho.reporting.engine.classic.core.layout.output.PerformanceProgressLogger - [Thread-16] Report Processing Finished: 8409ms - 5,946 rows/sec - Free: 38181048; Total: 183762944
    2014-10-29 10:14:58,288 [ 89770] DEBUG - org.pentaho.reporting.designer.core.util.ExternalToolLauncher - Running on operating system: Windows 7
    2014-10-29 10:14:58,288 [ 89770] DEBUG - org.pentaho.reporting.designer.core.util.ExternalToolLauncher - Detected Windows.
    2014-10-29 10:14:58,358 [ 89840] DEBUG - org.pentaho.reporting.designer.core.util.ExternalToolLauncher - ProcessWrapper exitCode = 0

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  
Privacy Policy | Legal Notices | Safe Harbor Privacy Policy

Copyright © 2005 - 2019 Hitachi Vantara Corporation. All Rights Reserved.