Hi Jeff,
Am Di., 24. März 2020 um 09:39 Uhr schrieb Jeff Zhang <zjf...@gmail.com>:
> Do you use the same version of spark for zeppelin 0.7 & 0.8 ? What kind of
> job do you run ? Is it easy to reproduce it ?
>
Zeppelin comes with spark 2.1.0 in 0.7.3 and spark 2.2.1 in 0.8.2, so
different version.
In this case it is a 'cache table ...' statement in the %spark.sql
interpreter and i see the larger delay in task executions everytime i
execute it with the different zeppelin versions.
BR,
Sebastian.
>
> Sebastian Albrecht <albrecht.sebast...@googlemail.com> 于2020年3月24日周二
> 下午4:24写道：
>
>> Hi,
>> i just upgraded from zeppelin 0.7.3 to 0.8.2. I am using zeppelin for
>> spark in local mode and 0.8.2 came with spark updated to 2.2.1. I now
>> experience slower spark job executions. I can show it in these log
>> snippets: task executions with 0.7.3: milliseconds, 0.8.2: seconds
>>
>> 0.7.3
>> INFO [2020-03-12 00:01:22,105] ({Executor task launch worker-2}
>> Logging.scala[logInfo]:54) - Code generated in 24.742647 ms
>> INFO [2020-03-12 00:01:22,139] ({Executor task launch worker-2}
>> Logging.scala[logInfo]:54) - Code generated in 23.640976 ms
>> INFO [2020-03-12 00:01:22,174] ({Executor task launch worker-2}
>> Logging.scala[logInfo]:54) - Code generated in 11.667064 ms
>> INFO [2020-03-12 00:01:22,193] ({Executor task launch worker-0}
>> Logging.scala[logInfo]:54) - Code generated in 14.959374 ms
>> INFO [2020-03-12 00:01:22,872] ({Executor task launch worker-6}
>> Logging.scala[logInfo]:54) - Finished task 6.0 in stage 8.0 (TID 14). 2593
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:22,873] ({dispatcher-event-loop-2}
>> Logging.scala[logInfo]:54) - Starting task 8.0 in stage 8.0 (TID 16,
>> localhost, executor driver, partition 8, NODE_LOCAL, 9086 bytes)
>> INFO [2020-03-12 00:01:22,875] ({Executor task launch worker-6}
>> Logging.scala[logInfo]:54) - Running task 8.0 in stage 8.0 (TID 16)
>> INFO [2020-03-12 00:01:22,876] ({task-result-getter-0}
>> Logging.scala[logInfo]:54) - Finished task 6.0 in stage 8.0 (TID 14) in
>> 2061 ms on localhost (executor driver) (1/97)
>> INFO [2020-03-12 00:01:22,938] ({Executor task launch worker-2}
>> Logging.scala[logInfo]:54) - Finished task 2.0 in stage 8.0 (TID 10). 2593
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:22,939] ({dispatcher-event-loop-7}
>> Logging.scala[logInfo]:54) - Starting task 9.0 in stage 8.0 (TID 17,
>> localhost, executor driver, partition 9, NODE_LOCAL, 8838 bytes)
>> INFO [2020-03-12 00:01:22,946] ({task-result-getter-1}
>> Logging.scala[logInfo]:54) - Finished task 2.0 in stage 8.0 (TID 10) in
>> 2135 ms on localhost (executor driver) (2/97)
>> INFO [2020-03-12 00:01:22,962] ({Executor task launch worker-8}
>> Logging.scala[logInfo]:54) - Running task 9.0 in stage 8.0 (TID 17)
>> INFO [2020-03-12 00:01:22,983] ({Executor task launch worker-3}
>> Logging.scala[logInfo]:54) - Finished task 3.0 in stage 8.0 (TID 11). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:22,984] ({dispatcher-event-loop-3}
>> Logging.scala[logInfo]:54) - Starting task 10.0 in stage 8.0 (TID 18,
>> localhost, executor driver, partition 10, NODE_LOCAL, 8839 bytes)
>> INFO [2020-03-12 00:01:22,985] ({task-result-getter-2}
>> Logging.scala[logInfo]:54) - Finished task 3.0 in stage 8.0 (TID 11) in
>> 2173 ms on localhost (executor driver) (3/97)
>> INFO [2020-03-12 00:01:22,986] ({Executor task launch worker-2}
>> Logging.scala[logInfo]:54) - Running task 10.0 in stage 8.0 (TID 18)
>> INFO [2020-03-12 00:01:23,068] ({Executor task launch worker-0}
>> Logging.scala[logInfo]:54) - Finished task 0.0 in stage 8.0 (TID 8). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:23,069] ({dispatcher-event-loop-6}
>> Logging.scala[logInfo]:54) - Starting task 11.0 in stage 8.0 (TID 19,
>> localhost, executor driver, partition 11, NODE_LOCAL, 9333 bytes)
>> INFO [2020-03-12 00:01:23,070] ({Executor task launch worker-3}
>> Logging.scala[logInfo]:54) - Running task 11.0 in stage 8.0 (TID 19)
>> INFO [2020-03-12 00:01:23,070] ({task-result-getter-3}
>> Logging.scala[logInfo]:54) - Finished task 0.0 in stage 8.0 (TID 8) in 2262
>> ms on localhost (executor driver) (4/97)
>> INFO [2020-03-12 00:01:23,088] ({Executor task launch worker-7}
>> Logging.scala[logInfo]:54) - Finished task 7.0 in stage 8.0 (TID 15). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:23,089] ({dispatcher-event-loop-2}
>> Logging.scala[logInfo]:54) - Starting task 12.0 in stage 8.0 (TID 20,
>> localhost, executor driver, partition 12, NODE_LOCAL, 8591 bytes)
>> INFO [2020-03-12 00:01:23,090] ({task-result-getter-0}
>> Logging.scala[logInfo]:54) - Finished task 7.0 in stage 8.0 (TID 15) in
>> 2275 ms on localhost (executor driver) (5/97)
>> INFO [2020-03-12 00:01:23,090] ({Executor task launch worker-7}
>> Logging.scala[logInfo]:54) - Running task 12.0 in stage 8.0 (TID 20)
>> INFO [2020-03-12 00:01:23,266] ({Executor task launch worker-1}
>> Logging.scala[logInfo]:54) - Finished task 1.0 in stage 8.0 (TID 9). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:23,267] ({dispatcher-event-loop-7}
>> Logging.scala[logInfo]:54) - Starting task 13.0 in stage 8.0 (TID 21,
>> localhost, executor driver, partition 13, NODE_LOCAL, 9458 bytes)
>> INFO [2020-03-12 00:01:23,268] ({task-result-getter-1}
>> Logging.scala[logInfo]:54) - Finished task 1.0 in stage 8.0 (TID 9) in 2457
>> ms on localhost (executor driver) (6/97)
>> INFO [2020-03-12 00:01:23,269] ({Executor task launch worker-1}
>> Logging.scala[logInfo]:54) - Running task 13.0 in stage 8.0 (TID 21)
>> INFO [2020-03-12 00:01:23,278] ({Executor task launch worker-4}
>> Logging.scala[logInfo]:54) - Finished task 4.0 in stage 8.0 (TID 12). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:23,279] ({dispatcher-event-loop-3}
>> Logging.scala[logInfo]:54) - Starting task 14.0 in stage 8.0 (TID 22,
>> localhost, executor driver, partition 14, NODE_LOCAL, 9086 bytes)
>> INFO [2020-03-12 00:01:23,279] ({Executor task launch worker-0}
>> Logging.scala[logInfo]:54) - Running task 14.0 in stage 8.0 (TID 22)
>> INFO [2020-03-12 00:01:23,280] ({task-result-getter-2}
>> Logging.scala[logInfo]:54) - Finished task 4.0 in stage 8.0 (TID 12) in
>> 2467 ms on localhost (executor driver) (7/97)
>> INFO [2020-03-12 00:01:23,773] ({Executor task launch worker-5}
>> Logging.scala[logInfo]:54) - Finished task 5.0 in stage 8.0 (TID 13). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:23,775] ({dispatcher-event-loop-6}
>> Logging.scala[logInfo]:54) - Starting task 15.0 in stage 8.0 (TID 23,
>> localhost, executor driver, partition 15, NODE_LOCAL, 8962 bytes)
>> INFO [2020-03-12 00:01:23,775] ({Executor task launch worker-5}
>> Logging.scala[logInfo]:54) - Running task 15.0 in stage 8.0 (TID 23)
>> INFO [2020-03-12 00:01:23,775] ({task-result-getter-3}
>> Logging.scala[logInfo]:54) - Finished task 5.0 in stage 8.0 (TID 13) in
>> 2961 ms on localhost (executor driver) (8/97)
>> INFO [2020-03-12 00:01:24,026] ({Executor task launch worker-2}
>> Logging.scala[logInfo]:54) - Finished task 10.0 in stage 8.0 (TID 18). 2506
>> bytes result sent to driver
>> INFO [2020-03-12 00:01:24,028] ({dispatcher-event-loop-2}
>> Logging.scala[logInfo]:54) - Starting task 16.0 in stage 8.0 (TID 24,
>> localhost, executor driver, partition 16, NODE_LOCAL, 8963 bytes)
>>
>> 0.8.2
>>
>> INFO [2020-03-17 15:39:14,699] ({Executor task launch worker for task
>> 410} Logging.scala[logInfo]:54) - Code generated in 7.739789 ms
>> INFO [2020-03-17 15:39:14,715] ({Executor task launch worker for task
>> 410} Logging.scala[logInfo]:54) - Code generated in 14.050658 ms
>> INFO [2020-03-17 15:39:14,921] ({Executor task launch worker for task
>> 410} Logging.scala[logInfo]:54) - Finished task 0.0 in stage 7.0 (TID 410).
>> 2055 bytes result sent to driver
>> INFO [2020-03-17 15:39:14,922] ({dispatcher-event-loop-3}
>> Logging.scala[logInfo]:54) - Starting task 1.0 in stage 7.0 (TID 411,
>> localhost, executor driver, partition 1, NODE_LOCAL, 7296 bytes)
>> INFO [2020-03-17 15:39:14,922] ({Executor task launch worker for task
>> 411} Logging.scala[logInfo]:54) - Running task 1.0 in stage 7.0 (TID 411)
>> INFO [2020-03-17 15:39:14,922] ({task-result-getter-2}
>> Logging.scala[logInfo]:54) - Finished task 0.0 in stage 7.0 (TID 410) in
>> 1171 ms on localhost (executor driver) (1/113)
>> INFO [2020-03-17 15:39:16,679] ({Executor task launch worker for task
>> 411} Logging.scala[logInfo]:54) - Finished task 1.0 in stage 7.0 (TID 411).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:16,680] ({dispatcher-event-loop-1}
>> Logging.scala[logInfo]:54) - Starting task 2.0 in stage 7.0 (TID 412,
>> localhost, executor driver, partition 2, NODE_LOCAL, 6923 bytes)
>> INFO [2020-03-17 15:39:16,680] ({Executor task launch worker for task
>> 412} Logging.scala[logInfo]:54) - Running task 2.0 in stage 7.0 (TID 412)
>> INFO [2020-03-17 15:39:16,680] ({task-result-getter-3}
>> Logging.scala[logInfo]:54) - Finished task 1.0 in stage 7.0 (TID 411) in
>> 1758 ms on localhost (executor driver) (2/113)
>> INFO [2020-03-17 15:39:17,584] ({Executor task launch worker for task
>> 412} Logging.scala[logInfo]:54) - Finished task 2.0 in stage 7.0 (TID 412).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:17,585] ({dispatcher-event-loop-7}
>> Logging.scala[logInfo]:54) - Starting task 3.0 in stage 7.0 (TID 413,
>> localhost, executor driver, partition 3, NODE_LOCAL, 7171 bytes)
>> INFO [2020-03-17 15:39:17,585] ({Executor task launch worker for task
>> 413} Logging.scala[logInfo]:54) - Running task 3.0 in stage 7.0 (TID 413)
>> INFO [2020-03-17 15:39:17,585] ({task-result-getter-0}
>> Logging.scala[logInfo]:54) - Finished task 2.0 in stage 7.0 (TID 412) in
>> 906 ms on localhost (executor driver) (3/113)
>> INFO [2020-03-17 15:39:18,811] ({Executor task launch worker for task
>> 413} Logging.scala[logInfo]:54) - Finished task 3.0 in stage 7.0 (TID 413).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:18,811] ({dispatcher-event-loop-6}
>> Logging.scala[logInfo]:54) - Starting task 4.0 in stage 7.0 (TID 414,
>> localhost, executor driver, partition 4, NODE_LOCAL, 6924 bytes)
>> INFO [2020-03-17 15:39:18,812] ({Executor task launch worker for task
>> 414} Logging.scala[logInfo]:54) - Running task 4.0 in stage 7.0 (TID 414)
>> INFO [2020-03-17 15:39:18,812] ({task-result-getter-1}
>> Logging.scala[logInfo]:54) - Finished task 3.0 in stage 7.0 (TID 413) in
>> 1228 ms on localhost (executor driver) (4/113)
>> INFO [2020-03-17 15:39:19,459] ({Executor task launch worker for task
>> 414} Logging.scala[logInfo]:54) - Finished task 4.0 in stage 7.0 (TID 414).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:19,460] ({dispatcher-event-loop-5}
>> Logging.scala[logInfo]:54) - Starting task 5.0 in stage 7.0 (TID 415,
>> localhost, executor driver, partition 5, NODE_LOCAL, 6923 bytes)
>> INFO [2020-03-17 15:39:19,460] ({Executor task launch worker for task
>> 415} Logging.scala[logInfo]:54) - Running task 5.0 in stage 7.0 (TID 415)
>> INFO [2020-03-17 15:39:19,460] ({task-result-getter-2}
>> Logging.scala[logInfo]:54) - Finished task 4.0 in stage 7.0 (TID 414) in
>> 649 ms on localhost (executor driver) (5/113)
>> INFO [2020-03-17 15:39:21,712] ({Executor task launch worker for task
>> 415} Logging.scala[logInfo]:54) - Finished task 5.0 in stage 7.0 (TID 415).
>> 2055 bytes result sent to driver
>> INFO [2020-03-17 15:39:21,712] ({dispatcher-event-loop-4}
>> Logging.scala[logInfo]:54) - Starting task 6.0 in stage 7.0 (TID 416,
>> localhost, executor driver, partition 6, NODE_LOCAL, 7915 bytes)
>> INFO [2020-03-17 15:39:21,712] ({Executor task launch worker for task
>> 416} Logging.scala[logInfo]:54) - Running task 6.0 in stage 7.0 (TID 416)
>> INFO [2020-03-17 15:39:21,712] ({task-result-getter-3}
>> Logging.scala[logInfo]:54) - Finished task 5.0 in stage 7.0 (TID 415) in
>> 2252 ms on localhost (executor driver) (6/113)
>> INFO [2020-03-17 15:39:22,406] ({Executor task launch worker for task
>> 416} Logging.scala[logInfo]:54) - Finished task 6.0 in stage 7.0 (TID 416).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:22,406] ({dispatcher-event-loop-6}
>> Logging.scala[logInfo]:54) - Starting task 7.0 in stage 7.0 (TID 417,
>> localhost, executor driver, partition 7, NODE_LOCAL, 7171 bytes)
>> INFO [2020-03-17 15:39:22,406] ({Executor task launch worker for task
>> 417} Logging.scala[logInfo]:54) - Running task 7.0 in stage 7.0 (TID 417)
>> INFO [2020-03-17 15:39:22,406] ({task-result-getter-0}
>> Logging.scala[logInfo]:54) - Finished task 6.0 in stage 7.0 (TID 416) in
>> 694 ms on localhost (executor driver) (7/113)
>> INFO [2020-03-17 15:39:23,407] ({Executor task launch worker for task
>> 417} Logging.scala[logInfo]:54) - Finished task 7.0 in stage 7.0 (TID 417).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:23,407] ({dispatcher-event-loop-5}
>> Logging.scala[logInfo]:54) - Starting task 8.0 in stage 7.0 (TID 418,
>> localhost, executor driver, partition 8, NODE_LOCAL, 7047 bytes)
>> INFO [2020-03-17 15:39:23,407] ({Executor task launch worker for task
>> 418} Logging.scala[logInfo]:54) - Running task 8.0 in stage 7.0 (TID 418)
>> INFO [2020-03-17 15:39:23,407] ({task-result-getter-1}
>> Logging.scala[logInfo]:54) - Finished task 7.0 in stage 7.0 (TID 417) in
>> 1001 ms on localhost (executor driver) (8/113)
>> INFO [2020-03-17 15:39:24,450] ({Executor task launch worker for task
>> 418} Logging.scala[logInfo]:54) - Finished task 8.0 in stage 7.0 (TID 418).
>> 2012 bytes result sent to driver
>> INFO [2020-03-17 15:39:24,450] ({dispatcher-event-loop-2}
>> Logging.scala[logInfo]:54) - Starting task 9.0 in stage 7.0 (TID 419,
>> localhost, executor driver, partition 9, NODE_LOCAL, 6924 bytes)
>>
>> I already gave zeppelin itself as well as the spark interpreter more Xmx.
>> Is this a spark only issue or what would you recommend to narrow down the
>> possible source for that performance fall.
>>
>> Thanks + BR,
>> Sebastian.
>>
>>
>
> --
> Best Regards
>
> Jeff Zhang
>
