Xamarin Android - Portable Общая библиотека Код работает невероятно медленно

Question

Я пытаюсь создать приложение с Xamarin. У меня есть портативная разделяемая библиотека с некоторым кодом, который требует времени для обработки. Я создал консольное приложение, которое использует эту библиотеку, и я также работаю над Android-приложением, которое использует одну и ту же портативную общую библиотеку с Xamarin.Android, однако общий переносимый код работает невероятно медленно на Android.

EDIT: Я также попытался поместить свой код в общий проект, а не в общую библиотеку, чтобы увидеть, будет ли он работать с нормальной скоростью, но это не помогло.

Я приурочены некоторые методы с секундомеров, как так:

Оригинальные

return p => p.EndsWith(endingString) 

С Секундомер

return (p => 
{ 
    Stopwatch sw = Stopwatch.StartNew(); 
    bool ans = p.EndsWith(endingString); 
    sw.Stop(); 
    Debug.WriteLine(sw.ElapsedTicks); 
    return ans; 
}); 

Андроида приложение очень медленно по некоторым причинам. В приведенном выше коде мне сказали, что просто проверить, заканчивается ли строка с чем-то примерно на 1411 тиков на Android, тогда как на моем компьютере потребовалось всего 5 тиков, а это означает, что версия Android на 280 раз больше тиков на Android.

Другой способ взял 243669 тиков на Android и 4561 тик на моем компьютере, то есть потребовалось 53x столько тиков.

Метод ниже взял 19847785 тиков на Android и 819619 на моем компьютере, будучи в 24 раза медленнее. Я не думаю, что медленность вызвана моим кодом, но я хотел бы привести пример некоторых из моего кода, на всякий случай, это вызвано чем-то в моем коде.

private void InitialiseFrequencyDictionary() 
{ 
    if (_frequencyDictionary != null) return; 
    StreamReader streamReader = EmbeddedResourceGetter.GetFrequencyListStreamReader(); 
    _frequencyDictionary = new Dictionary<string, string>(); 
    string line; 

    while (!string.IsNullOrEmpty(line = streamReader.ReadLine())) 
    { 
     try 
     { 
      string[] lineSplit = line.Split(new[] {' '}, 2); 
      _frequencyDictionary.Add(lineSplit[0], lineSplit[1]); 
     } 
     catch { /* ignored */ } 
    } 
} 

публичного метод целых классов в целом принял 155524065 тиков на Android и взял 15761ms. На моем компьютере было занято 2471652 тика и 1152 мс, а это значит, что на Android было занято 63 раза больше, а на Android - на 15 раз больше, чем на моем компьютере.

Я знаю, что эти результаты не совсем точны, поскольку я тестирую их на разных устройствах, разных ОС и разных архитектурах, но мне не кажется, что они точно отражают разницу в производительности между моим компьютером и моим телефоном. Мой телефон оценивает 1219 и 4273 в Geekbench, в одном ядре и многоядерном баллах соответственно, а мой компьютер оценивает 3288 и 6978 на Geekbench. Это означает, что мой телефон должен быть на 3 раза медленнее, чем мой компьютер, а не 16x!

Всякий раз, когда этот код выполняется на моем устройстве Android, я получаю много сообщений от сборщика мусора (я думаю) в разделе «Вывод» Visual Studio.

01-08 18:48:27.527 D/Mono (9357): GC_MINOR: (Nursery full) pause 0.90ms, total 1.08ms, bridge 0.00ms promoted 880K major 880K los 8K 
01-08 18:48:30.133 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:30.133 D/Mono (9357): GC_MINOR: (Nursery full) pause 0.85ms, total 0.98ms, bridge 0.00ms promoted 880K major 880K los 8K 
01-08 18:48:32.760 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:32.760 D/Mono (9357): GC_MINOR: (Nursery full) pause 1.81ms, total 2.06ms, bridge 0.00ms promoted 896K major 896K los 8K 
01-08 18:48:35.034 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:35.034 D/Mono (9357): GC_MINOR: (Nursery full) pause 1.19ms, total 1.37ms, bridge 0.00ms promoted 912K major 912K los 8K 
01-08 18:48:37.687 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:37.687 D/Mono (9357): GC_MINOR: (Nursery full) pause 0.59ms, total 1.61ms, bridge 0.00ms promoted 912K major 912K los 8K 
01-08 18:48:39.298 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.298 D/Mono (9357): GC_MINOR: (Nursery full) pause 4.78ms, total 5.13ms, bridge 0.00ms promoted 1248K major 1248K los 296K 
01-08 18:48:39.378 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.378 D/Mono (9357): GC_MINOR: (Nursery full) pause 7.58ms, total 7.81ms, bridge 0.00ms promoted 2336K major 2336K los 1348K 
01-08 18:48:39.459 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.459 D/Mono (9357): GC_MINOR: (Nursery full) pause 7.24ms, total 7.46ms, bridge 0.00ms promoted 3488K major 3488K los 2821K 
01-08 18:48:39.536 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.536 D/Mono (9357): GC_MINOR: (Nursery full) pause 6.13ms, total 6.40ms, bridge 0.00ms promoted 4624K major 4624K los 2821K 
01-08 18:48:39.627 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.627 D/Mono (9357): GC_MINOR: (Nursery full) pause 8.29ms, total 8.51ms, bridge 0.00ms promoted 5776K major 5776K los 5877K 
01-08 18:48:39.705 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.705 D/Mono (9357): GC_MINOR: (Nursery full) pause 6.47ms, total 6.68ms, bridge 0.00ms promoted 6832K major 6832K los 5877K 
01-08 18:48:39.796 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.796 D/Mono (9357): GC_MINOR: (Nursery full) pause 15.16ms, total 16.35ms, bridge 0.00ms promoted 7888K major 7888K los 5877K 
01-08 18:48:39.876 D/Mono (9357): GC_OLD_BRIDGE num-objects 23 num_hash_entries 29 sccs size 29 init 0.00ms df1 0.05ms sort 0.00ms dfs2 0.09ms setup-cb 0.01ms free-data 0.03ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:39.876 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.47ms, total 5.68ms, bridge 0.00ms promoted 8928K major 8928K los 5877K 
01-08 18:48:40.031 I/art  (9357): Explicit concurrent mark sweep GC freed 6197(237KB) AllocSpace objects, 0(0B) LOS objects, 45% free, 4MB/8MB, paused 1.286ms total 18.093ms 
01-08 18:48:40.032 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 7/7/7/1 dfs passes 52/31 
01-08 18:48:40.032 D/Mono (9357): GC_MAJOR: (Minor allowance) pause 33.66ms, total 36.59ms, bridge 0.00ms major 9968K/0K los 8789K/0K 
01-08 18:48:40.110 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.110 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.65ms, total 5.88ms, bridge 0.00ms promoted 11008K major 11008K los 8789K 
01-08 18:48:40.190 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.190 D/Mono (9357): GC_MINOR: (Nursery full) pause 6.16ms, total 6.37ms, bridge 0.00ms promoted 12032K major 12032K los 8789K 
01-08 18:48:40.283 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.283 D/Mono (9357): GC_MINOR: (Nursery full) pause 14.61ms, total 17.42ms, bridge 0.00ms promoted 13104K major 13104K los 8789K 
01-08 18:48:40.373 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.373 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.86ms, total 6.18ms, bridge 0.00ms promoted 14144K major 14144K los 8789K 
01-08 18:48:40.455 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.455 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.82ms, total 6.05ms, bridge 0.00ms promoted 15168K major 15168K los 8789K 
01-08 18:48:40.536 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.06ms sort 0.01ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.536 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.51ms, total 5.72ms, bridge 0.00ms promoted 16224K major 16224K los 8789K 
01-08 18:48:40.772 I/art  (9357): Explicit concurrent mark sweep GC freed 338(11KB) AllocSpace objects, 0(0B) LOS objects, 45% free, 4MB/8MB, paused 838us total 17.067ms 
01-08 18:48:40.772 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 7/7/7/1 dfs passes 52/31 
01-08 18:48:40.773 D/Mono (9357): GC_MAJOR: (Minor allowance) pause 74.78ms, total 78.16ms, bridge 0.00ms major 17264K/0K los 18218K/0K 
01-08 18:48:40.850 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.850 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.58ms, total 5.81ms, bridge 0.00ms promoted 18304K major 18304K los 18218K 
01-08 18:48:40.929 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:40.929 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.98ms, total 6.53ms, bridge 0.00ms promoted 19344K major 19344K los 18218K 
01-08 18:48:41.008 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:41.008 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.53ms, total 5.74ms, bridge 0.00ms promoted 20400K major 20400K los 18218K 
01-08 18:48:41.089 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:41.089 D/Mono (9357): GC_MINOR: (Nursery full) pause 7.68ms, total 7.74ms, bridge 0.00ms promoted 21440K major 21440K los 18230K 
01-08 18:48:41.168 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:41.168 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.56ms, total 5.77ms, bridge 0.00ms promoted 22496K major 22496K los 18230K 
01-08 18:48:41.247 D/Mono (9357): GC_OLD_BRIDGE num-objects 21 num_hash_entries 24 sccs size 24 init 0.00ms df1 0.05ms sort 0.02ms dfs2 0.06ms setup-cb 0.01ms free-data 0.02ms links 0/0/0/0 dfs passes 0/0 
01-08 18:48:41.247 D/Mono (9357): GC_MINOR: (Nursery full) pause 5.64ms, total 6.09ms, bridge 0.00ms promoted 23520K major 23520K los 18230K 

Так это медленность нормально для Xamarin? Это ошибка в Xamarin, или есть что-то, что мне не хватает? Это что-то вызвано сборщиком мусора?

Answer 1

Я исследовал немного больше. Эта проблема возникает не только при использовании PCL, но и при наличии списка слов в Android Assets.

Сначала я пытался что-то вроде этого:

public static async Task<Dictionary<string, int>> ReadWordFrequenciesAsync(Stream stream) 
{ 
    var freqs = new Dictionary<string, int>(); 

    using (var reader = new StreamReader(stream)) 
    { 
     string line; 
     while ((line = await reader.ReadLineAsync().ConfigureAwait(false)) != null) 
     { 
      var split = line.Split(' '); 
      var word = split[0]; 
      var frequency = 0; 

      if (int.TryParse(split[1], out frequency)) 
       freqs.Add(word, frequency); 

      line = null; 
     } 
    } 

    return freqs; 
} 

public static Stream GetWordListFromPcl() 
{ 
    var assembly = typeof(WordListReader).GetTypeInfo().Assembly; 
    return assembly.GetManifestResourceStream("WordList.Content.en.txt"); 
} 

Это потребовалось 54 мс на моем компьютере, и около 8 более секунд на моем Nexus 5.

Изменение кода не разобрать частоту на междунар так:

public static async Task<Dictionary<string, string>> ReadWordFrequenciesAsync(Stream stream = null) 
{ 
    var freqs = new Dictionary<string, string>(); 

    using (var reader = new StreamReader(stream)) 
    { 
     string line; 
     while ((line = await reader.ReadLineAsync().ConfigureAwait(false)) != null) 
     { 
      var split = line.Split(' '); 
      var word = split[0]; 
      var frequency = split[1]; 
      freqs.Add(word, frequency); 

      line = null; 
     } 
    } 

    return freqs; 
} 

Это сделало код 2 секунды быстрее на Nexus 5.

Я попробовал то же самое только с Android активов где Я прочитал поток как:

var stream = Assets.Open("en.txt"); 

Это привело к идентичному времени считывания. Это означает, что PCL не виноват.

Последнее, что я пробовал, - это прочитать весь файл в памяти. Например:

public static async Task<string> ReadWordFrequenciesStringAsync(Stream stream = null) 
{ 
    using (var reader = new StreamReader(stream)) 
    { 
     return await reader.ReadToEndAsync().ConfigureAwait(false); 
    } 
} 

Это занимает меньше секунды!

ОК, так что же такое заключение? Я думаю, что метод line.Split является виновным! Что мы можем сделать вместо этого?

Мы можем попробовать реализовать собственный разделитель. Пробовал что-то вроде этого:

public static class StringExtensions 
{ 
    public static Tuple<string, string> MySplit(this string s, char c) 
    { 
     var l = s.Length; 
     for (var i = 0; i < l; i++) 
     { 
      if (s[i] == c) 
      { 
       return new Tuple<string, string>(s.Substring(0, i), s.Substring(i + 1)); 
      } 
     } 

     return null; 
    } 
} 

Это спасло целую секунду, все еще анализируя значение частоты до значения int. Производительность MySplit такая же, если вместо этого использовать string[] в качестве возвращаемого значения, чтобы получить там немного.

Использование небезопасного кода может помочь в производительности здесь. Но время на самом деле не читает файл, а анализирует его.