Пожалуйста, помогите мне понять эти следы Clojure Hprof
У меня есть некоторый код Clojure, который моделирует и затем обрабатывает числовые данные. Данные в основном являются векторами двойных значений; обработка главным образом включает суммирование их значений различными способами. Я приведу код ниже, но мой вопрос (я думаю) более общий - я просто не знаю, как интерпретировать результаты hprof.
Во всяком случае, мой тестовый код:
(defn spin [n]
(let [c 6000
signals (spin-signals c)]
(doseq [_ (range n)] (time (spin-voxels c signals)))))
(defn -main []
(spin 4))
где spin-voxels должно быть дороже, чем spin-signals (особенно при многократном повторении). Я могу дать процедуры более низкого уровня, но я думаю, что этот вопрос больше касается меня, а не понимания основ трассировки (ниже).
Когда я компилирую это с помощью lein, а затем выполняю простое профилирование:
> java -cp classes:lib/clojure-1.3.0-beta1.jar -agentlib:hprof=cpu=samples,depth=10,file=hprof.vec com.isti.compset.stack
"Elapsed time: 14118.772924 msecs"
"Elapsed time: 10082.015672 msecs"
"Elapsed time: 9212.522973 msecs"
"Elapsed time: 12968.23877 msecs"
Dumping CPU usage by sampling running threads ... done.
и трассировка профиля выглядит так:
CPU SAMPLES BEGIN (total = 4300) Sun Aug 28 15:51:40 2011
rank self accum count trace method
1 5.33% 5.33% 229 300791 clojure.core$seq.invoke
2 5.21% 10.53% 224 300786 clojure.core$seq.invoke
3 5.05% 15.58% 217 300750 clojure.core$seq.invoke
4 4.93% 20.51% 212 300787 clojure.lang.Numbers.add
5 4.74% 25.26% 204 300799 clojure.core$seq.invoke
6 2.60% 27.86% 112 300783 clojure.lang.RT.more
7 2.51% 30.37% 108 300803 clojure.lang.Numbers.multiply
8 2.42% 32.79% 104 300788 clojure.lang.RT.first
9 2.37% 35.16% 102 300831 clojure.lang.RT.more
10 2.37% 37.53% 102 300840 clojure.lang.Numbers.add
что довольно круто До здесь я счастлив. Я вижу, что я трачу время на общую обработку числовых значений.
Поэтому я смотрю на свой код и решаю, что в качестве первого шага я заменю vec с d-vec:
(defn d-vec [collection]
(apply conj (vector-of :double) collection))
Я не уверен, что этого будет достаточно - я подозреваю, что мне также нужно будет добавить аннотации некоторых типов в разных местах - но это кажется хорошим началом. Поэтому я снова компилирую и профилирую:
> java -cp classes:lib/clojure-1.3.0-beta1.jar -agentlib:hprof=cpu=samples,depth=10,file=hprof.d-vec com.isti.compset.stack
"Elapsed time: 15944.278043 msecs"
"Elapsed time: 15608.099677 msecs"
"Elapsed time: 16561.659408 msecs"
"Elapsed time: 15416.414548 msecs"
Dumping CPU usage by sampling running threads ... done.
Ewww. Так что это значительно медленнее. А профиль?
CPU SAMPLES BEGIN (total = 6425) Sun Aug 28 15:55:12 2011
rank self accum count trace method
1 26.16% 26.16% 1681 300615 clojure.core.Vec.count
2 23.28% 49.45% 1496 300607 clojure.core.Vec.count
3 7.74% 57.18% 497 300608 clojure.lang.RT.seqFrom
4 5.59% 62.77% 359 300662 clojure.core.Vec.count
5 3.72% 66.49% 239 300604 clojure.lang.RT.first
6 3.25% 69.74% 209 300639 clojure.core.Vec.count
7 1.91% 71.66% 123 300635 clojure.core.Vec.count
8 1.03% 72.68% 66 300663 clojure.core.Vec.count
9 1.00% 73.68% 64 300644 clojure.lang.RT.more
10 0.79% 74.47% 51 300666 clojure.lang.RT.first
11 0.75% 75.22% 48 300352 clojure.lang.Numbers.double_array
12 0.75% 75.97% 48 300638 clojure.lang.RT.more
13 0.64% 76.61% 41 300621 clojure.core.Vec.count
14 0.62% 77.23% 40 300631 clojure.core.Vec.cons
15 0.61% 77.84% 39 300025 java.lang.ClassLoader.defineClass1
16 0.59% 78.43% 38 300670 clojure.core.Vec.cons
17 0.58% 79.00% 37 300681 clojure.core.Vec.cons
18 0.54% 79.55% 35 300633 clojure.lang.Numbers.multiply
19 0.48% 80.03% 31 300671 clojure.lang.RT.seqFrom
20 0.47% 80.50% 30 300609 clojure.lang.Numbers.add
Я включил здесь больше строк, потому что это та часть, которую я не понимаю.
Почему на земле Vec.count появляются так часто? Это метод, который возвращает размер вектора. Однострочный поиск атрибута.
Я предполагаю, что я медленнее, потому что я все еще прыгаю вперед и назад между Double и double, и что все может снова улучшиться, когда я добавлю больше аннотаций типов. Но я не понимаю, что у меня сейчас, поэтому я не уверен, что грубые промахи имеют большой смысл.
Пожалуйста, кто-нибудь может объяснить дамп выше в общих чертах? Я обещаю, что не буду повторно звонить count - вместо этого у меня есть много карт и сокращений и несколько явных циклов.
Я задавался вопросом, возможно, меня смущает JIT? Может быть, мне не хватает кучи информации, потому что функции встроены? О, и я использую 1.3.0-бета1, потому что он, кажется, имеет более разумную обработку чисел.
[ОБНОВЛЕНИЕ] Я кратко изложил свой опыт на http://www.acooke.org/cute/Optimising1.html - получил ускорение в 5 раз (на самом деле было 10 раз после очистки еще немного и переход на 1,3), несмотря на то, что никогда не понимал этого.
2 ответа
Вызов seq для объекта Vec (объекта, созданного vector-of) создает объект VecSeq.
Объект VecSeq, созданный в Veca, вызывает Vec.count в своем методе internal-Reduce, который используется clojure.core / redux.
так что кажется, что вектор, созданный vector-of вызывает Vec.count при сокращении. И как вы упомянули, что код сделал много сокращения, это, кажется, причина
То, что остается пугающим, - то, что Vec.count - то, что Vec.count, кажется, очень прост:
clojure.lang.Counted
(count [_] cnt)
простой добытчик, который не делает никакого подсчета.
Просто говоря вслух, похоже, что ваш код выполняет много конвертаций в / из Seq.
Глядя на RT.seqFrom, это вызывает ArraySeq.createFromObject
if(array == null || Array.getLength(array) == 0)
return null;
Таким образом, при использовании vec используется быстрый векторный доступ, а при использовании d-vec использование массивов и вызов медленного метода java.lang.Array.getLength (который использует отражение...)